??????
cloudstack4.5????????????Centos6.5??KVM????
??????
????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????
??????????
org.libvirt.LibvirtException: internal error Process exited while reading
console log output: Supported machines are:
pc RHEL 6.5.0 PC (alias of rhel6.5.0)
rhel6.5.0 RHEL 6.5.0 PC (default)
rhel6.4.0 RHEL 6.4.0 PC
rhel6.3.0 RHEL 6.3.0 PC
rhel6.2.0 RHEL 6.2.0 PC
rhel6.1.0 RHEL 6.1.0 PC
rhel6.0.0 RHEL 6.0.0 PC
rhel5.5.0 RHEL 5.5.0 PC
rhel5.4.4 RHEL 5.4.4 PC
rhel5.4.0 RHEL 5.4.0 PC
????????????????
2015-08-28 11:58:05,897 DEBUG [c.c.a.ApiServlet]
(catalina-exec-17:ctx-8a58f8fd) ===START=== 192.168.0.223 -- GET
command=findHostsForMigration&VirtualMachineId=4b4a6f98-e289-4157-b4e8-ac7952919499&response=json&sessionkey=AbKJjZThFS2gUfobXgviVBM%2BwlI%3D&_=1440734282554
2015-08-28 11:58:05,929 DEBUG [c.c.s.ManagementServerImpl]
(catalina-exec-17:ctx-8a58f8fd ctx-5a6924e1) Searching for all hosts in cluster
1 for migrating VM VM[User|i-2-13-VM]
2015-08-28 11:58:05,939 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(catalina-exec-17:ctx-8a58f8fd ctx-5a6924e1) Looking for hosts in dc: 1 pod:1
cluster:1
2015-08-28 11:58:05,953 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(catalina-exec-17:ctx-8a58f8fd ctx-5a6924e1) FirstFitAllocator has 2 hosts to
check for allocation: [Host[-4-Routing], Host[-1-Routing]]
2015-08-28 11:58:05,969 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(catalina-exec-17:ctx-8a58f8fd ctx-5a6924e1) Found 2 hosts for allocation after
prioritization: [Host[-4-Routing], Host[-1-Routing]]
2015-08-28 11:58:05,969 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(catalina-exec-17:ctx-8a58f8fd ctx-5a6924e1) Looking for speed=1000Mhz, Ram=1024
2015-08-28 11:58:05,969 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(catalina-exec-17:ctx-8a58f8fd ctx-5a6924e1) Host name: csca.dtscn.com, hostId:
4 is in avoid set, skipping this and trying other available hosts
2015-08-28 11:58:05,997 DEBUG [c.c.c.CapacityManagerImpl]
(catalina-exec-17:ctx-8a58f8fd ctx-5a6924e1) Host: 1 has cpu capability
(cpu:32, speed:2401) to support requested CPU: 1 and requested speed: 1000
2015-08-28 11:58:05,997 DEBUG [c.c.c.CapacityManagerImpl]
(catalina-exec-17:ctx-8a58f8fd ctx-5a6924e1) Checking if host: 1 has enough
capacity for requested CPU: 1000 and requested RAM: 1073741824 ,
cpuOverprovisioningFactor: 1.0
2015-08-28 11:58:06,007 DEBUG [c.c.c.CapacityManagerImpl]
(catalina-exec-17:ctx-8a58f8fd ctx-5a6924e1) Hosts's actual total CPU: 76832
and CPU after applying overprovisioning: 76832
2015-08-28 11:58:06,007 DEBUG [c.c.c.CapacityManagerImpl]
(catalina-exec-17:ctx-8a58f8fd ctx-5a6924e1) considerReservedCapacity isfalse ,
not considering reserved capacity for calculating free capacity
2015-08-28 11:58:06,007 DEBUG [c.c.c.CapacityManagerImpl]
(catalina-exec-17:ctx-8a58f8fd ctx-5a6924e1) Free CPU: 60332 , Requested CPU:
1000
2015-08-28 11:58:06,007 DEBUG [c.c.c.CapacityManagerImpl]
(catalina-exec-17:ctx-8a58f8fd ctx-5a6924e1) Free RAM: 49714814976 , Requested
RAM: 1073741824
2015-08-28 11:58:06,007 DEBUG [c.c.c.CapacityManagerImpl]
(catalina-exec-17:ctx-8a58f8fd ctx-5a6924e1) Host has enough CPU and RAM
available
2015-08-28 11:58:06,007 DEBUG [c.c.c.CapacityManagerImpl]
(catalina-exec-17:ctx-8a58f8fd ctx-5a6924e1) STATS: Can alloc CPU from host: 1,
used: 16500, reserved: 0, actual total: 76832, total with overprovisioning:
76832; requested cpu:1000,alloc_from_last_host?:false
,considerReservedCapacity?: false
2015-08-28 11:58:06,007 DEBUG [c.c.c.CapacityManagerImpl]
(catalina-exec-17:ctx-8a58f8fd ctx-5a6924e1) STATS: Can alloc MEM from host: 1,
used: 17716740096, reserved: 0, total: 67431555072; requested mem:
1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: false
2015-08-28 11:58:06,007 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(catalina-exec-17:ctx-8a58f8fd ctx-5a6924e1) Found a suitable host, adding to
list: 1
2015-08-28 11:58:06,007 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(catalina-exec-17:ctx-8a58f8fd ctx-5a6924e1) Host Allocator returning 1
suitable hosts
2015-08-28 11:58:06,007 DEBUG [c.c.s.ManagementServerImpl]
(catalina-exec-17:ctx-8a58f8fd ctx-5a6924e1) Hosts having capacity and suitable
for migration: [Host[-1-Routing]]
2015-08-28 11:58:06,038 DEBUG [c.c.a.ApiServlet] (catalina-exec-17:ctx-8a58f8fd
ctx-5a6924e1) ===END=== 192.168.0.223 -- GET
command=findHostsForMigration&VirtualMachineId=4b4a6f98-e289-4157-b4e8-ac7952919499&response=json&sessionkey=AbKJjZThFS2gUfobXgviVBM%2BwlI%3D&_=1440734282554
2015-08-28 11:58:06,052 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-c248cff6) Begin cleanup expired async-jobs
2015-08-28 11:58:06,068 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-c248cff6) End cleanup expired async-jobs
2015-08-28 11:58:06,395 DEBUG [c.c.n.ExternalDeviceUsageManagerImpl]
(ExternalNetworkMonitor-1:ctx-f13bbd26) External devices stats collector is
running...
2015-08-28 11:58:06,537 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
(SnapshotPollTask:ctx-7f2e44b6) Snapshot scheduler.poll is being called at
2015-08-28 03:58:06 GMT
2015-08-28 11:58:06,539 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
(SnapshotPollTask:ctx-7f2e44b6) Got 0 snapshots to be executed at 2015-08-28
03:58:06 GMT
2015-08-28 11:58:06,574 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-f7c4f1e0) Found 0 routers to update status.
2015-08-28 11:58:06,571 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterMonitor-1:ctx-f3461566) Found 0 running routers.
2015-08-28 11:58:06,576 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-f7c4f1e0) Found 0 networks to update RvR status.
2015-08-28 11:58:08,036 DEBUG [c.c.a.ApiServlet]
(catalina-exec-11:ctx-e7f0ac20) ===START=== 192.168.0.223 -- GET
command=migrateVirtualMachine&hostid=443d21e6-6303-415c-935e-b9e56a99d32b&virtualmachineid=4b4a6f98-e289-4157-b4e8-ac7952919499&response=json&sessionkey=AbKJjZThFS2gUfobXgviVBM%2BwlI%3D&_=1440734284695
2015-08-28 11:58:08,075 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-8:null) Ping from 2
2015-08-28 11:58:08,126 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-2:ctx-a0dd1522 job-245) Add job-245 into job monitoring
2015-08-28 11:58:08,137 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(catalina-exec-11:ctx-e7f0ac20 ctx-142a3e58) submit async job-245, details:
AsyncJobVO {id:245, userId: 2, accountId: 2, instanceType: None, instanceId:
null, cmd: org.apache.cloudstack.api.command.admin.vm.MigrateVMCmd, cmdInfo:
{"response":"json","sessionkey":"AbKJjZThFS2gUfobXgviVBM+wlI\u003d","ctxDetails":"{\"com.cloud.vm.VirtualMachine\":\"4b4a6f98-e289-4157-b4e8-ac7952919499\",\"com.cloud.host.Host\":\"443d21e6-6303-415c-935e-b9e56a99d32b\"}","virtualmachineid":"4b4a6f98-e289-4157-b4e8-ac7952919499","cmdEventType":"VM.MIGRATE","hostid":"443d21e6-6303-415c-935e-b9e56a99d32b","ctxUserId":"2","httpmethod":"GET","_":"1440734284695","ctxAccountId":"2","ctxStartEventId":"830"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 90520733719330, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null}
2015-08-28 11:58:08,142 DEBUG [c.c.a.ApiServlet] (catalina-exec-11:ctx-e7f0ac20
ctx-142a3e58) ===END=== 192.168.0.223 -- GET
command=migrateVirtualMachine&hostid=443d21e6-6303-415c-935e-b9e56a99d32b&virtualmachineid=4b4a6f98-e289-4157-b4e8-ac7952919499&response=json&sessionkey=AbKJjZThFS2gUfobXgviVBM%2BwlI%3D&_=1440734284695
2015-08-28 11:58:08,144 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-2:ctx-a0dd1522 job-245) Executing AsyncJobVO {id:245, userId:
2, accountId: 2, instanceType: None, instanceId: null, cmd:
org.apache.cloudstack.api.command.admin.vm.MigrateVMCmd, cmdInfo:
{"response":"json","sessionkey":"AbKJjZThFS2gUfobXgviVBM+wlI\u003d","ctxDetails":"{\"com.cloud.vm.VirtualMachine\":\"4b4a6f98-e289-4157-b4e8-ac7952919499\",\"com.cloud.host.Host\":\"443d21e6-6303-415c-935e-b9e56a99d32b\"}","virtualmachineid":"4b4a6f98-e289-4157-b4e8-ac7952919499","cmdEventType":"VM.MIGRATE","hostid":"443d21e6-6303-415c-935e-b9e56a99d32b","ctxUserId":"2","httpmethod":"GET","_":"1440734284695","ctxAccountId":"2","ctxStartEventId":"830"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 90520733719330, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null}
2015-08-28 11:58:08,224 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-2:ctx-a0dd1522 job-245 ctx-a2d1c6bd) Collect vm disk
statistics from host before stopping Vm
2015-08-28 11:58:08,247 DEBUG [c.c.a.t.Request]
(API-Job-Executor-2:ctx-a0dd1522 job-245 ctx-a2d1c6bd) Seq
4-1242993497154256919: Received: { Ans: , MgmtId: 90520733719330, via: 4, Ver:
v1, Flags: 10, { GetVmDiskStatsAnswer } }
2015-08-28 11:58:08,248 DEBUG [c.c.a.m.AgentManagerImpl]
(API-Job-Executor-2:ctx-a0dd1522 job-245 ctx-a2d1c6bd) Details from executing
class com.cloud.agent.api.GetVmDiskStatsCommand:
2015-08-28 11:58:08,275 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-2:ctx-a0dd1522 job-245 ctx-a2d1c6bd) Sync job-246 execution
on object VmWorkJobQueue.13
2015-08-28 11:58:08,290 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-10:null) Ping from 4
2015-08-28 11:58:08,294 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) Process host VM state report from ping process.
host: 4
2015-08-28 11:58:08,336 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) Process VM state report. host: 4, number of
records in report: 8
2015-08-28 11:58:08,336 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) VM state report. host: 4, vm id: 1, power state:
PowerOn
2015-08-28 11:58:08,340 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) VM power state does not change, skip DB writing.
vm id: 1
2015-08-28 11:58:08,341 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) VM state report. host: 4, vm id: 2, power state:
PowerOn
2015-08-28 11:58:08,349 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) VM power state does not change, skip DB writing.
vm id: 2
2015-08-28 11:58:08,349 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) VM state report. host: 4, vm id: 4, power state:
PowerOn
2015-08-28 11:58:08,356 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) VM power state does not change, skip DB writing.
vm id: 4
2015-08-28 11:58:08,356 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) VM state report. host: 4, vm id: 5, power state:
PowerOn
2015-08-28 11:58:08,360 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) VM power state does not change, skip DB writing.
vm id: 5
2015-08-28 11:58:08,360 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) VM state report. host: 4, vm id: 6, power state:
PowerOn
2015-08-28 11:58:08,364 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) VM power state does not change, skip DB writing.
vm id: 6
2015-08-28 11:58:08,364 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) VM state report. host: 4, vm id: 10, power
state: PowerOn
2015-08-28 11:58:08,368 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) VM power state does not change, skip DB writing.
vm id: 10
2015-08-28 11:58:08,368 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) VM state report. host: 4, vm id: 11, power
state: PowerOn
2015-08-28 11:58:08,373 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) VM power state does not change, skip DB writing.
vm id: 11
2015-08-28 11:58:08,373 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) VM state report. host: 4, vm id: 13, power
state: PowerOn
2015-08-28 11:58:08,377 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) VM power state does not change, skip DB writing.
vm id: 13
2015-08-28 11:58:08,392 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-10:null) Done with process of VM state report. host: 4
2015-08-28 11:58:09,402 DEBUG [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-1893e656) Zone 1 is ready to launch console proxy
2015-08-28 11:58:10,057 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-3ec8c824) Execute sync-queue item: SyncQueueItemVO
{id:2, queueId: 89, contentType: AsyncJob, contentId: 246, lastProcessMsid:
90520733719330, lastprocessNumber: 8, lastProcessTime: Fri Aug 28 11:58:10 CST
2015, created: Fri Aug 28 11:58:08 CST 2015}
2015-08-28 11:58:10,059 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-3ec8c824) Schedule queued job-246
2015-08-28 11:58:10,076 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246) Add job-246 into job
monitoring
2015-08-28 11:58:10,088 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246) Executing AsyncJobVO
{id:246, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd:
com.cloud.vm.VmWorkMigrate, cmdInfo:
rO0ABXNyABpjb20uY2xvdWQudm0uVm1Xb3JrTWlncmF0ZRdxQXtPtzYqAgAGSgAJc3JjSG9zdElkTAAJY2x1c3RlcklkdAAQTGphdmEvbGFuZy9Mb25nO0wABmhvc3RJZHEAfgABTAAFcG9kSWRxAH4AAUwAB3N0b3JhZ2V0AA9MamF2YS91dGlsL01hcDtMAAZ6b25lSWRxAH4AAXhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAADXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAABHNyAA5qYXZhLmxhbmcuTG9uZzuL5JDMjyPfAgABSgAFdmFsdWV4cgAQamF2YS5sYW5nLk51bWJlcoaslR0LlOCLAgAAeHAAAAAAAAAAAXEAfgAJcQB-AAlwcQB-AAk,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 90520733719330, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Fri Aug 28 11:58:08 CST 2015}
2015-08-28 11:58:10,089 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246) Run VM work job:
com.cloud.vm.VmWorkMigrate for VM 13, job origin: 245
2015-08-28 11:58:10,092 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) Execute VM work
job:
com.cloud.vm.VmWorkMigrate{"zoneId":1,"podId":1,"clusterId":1,"hostId":1,"srcHostId":4,"userId":2,"accountId":2,"vmId":13,"handlerName":"VirtualMachineManagerImpl"}
2015-08-28 11:58:10,104 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) Migrating
VM[User|i-2-13-VM] to
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2015-08-28 11:58:10,175 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) Preparing 1
volumes for VM[User|i-2-13-VM]
2015-08-28 11:58:10,274 DEBUG [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-cad9d76d) Zone 1 is ready to launch secondary storage VM
2015-08-28 11:58:10,283 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) Seq
1-2719892699955068952: Sending { Cmd , MgmtId: 90520733719330, via:
1(cscb.dtscn.com), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.PrepareForMigrationCommand":{"vm":{"id":13,"name":"i-2-13-VM","type":"User","cpus":1,"minSpeed":1000,"maxSpeed":1000,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"Windows
Server 2008 R2 (64-bit)","platformEmulator":"Windows Server
2008","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"SkhNAKeuF7dyCiy4c94YXA==","params":{},"uuid":"4b4a6f98-e289-4157-b4e8-ac7952919499","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"3d9e6024-8aab-4a62-9823-68f5f4dea8c0","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ffe66fef-cfe7-3257-9be4-a6fbc54dc6bf","id":1,"poolType":"NetworkFilesystem","host":"116.6.116.12","path":"/data/nfs/cs/jb/pri","port":2049,"url":"NetworkFilesystem://116.6.116.12/data/nfs/cs/jb/pri/?ROLE=Primary&STOREUUID=ffe66fef-cfe7-3257-9be4-a6fbc54dc6bf"}},"name":"ROOT-13","size":21474836480,"path":"3d9e6024-8aab-4a62-9823-68f5f4dea8c0","volumeId":17,"vmName":"i-2-13-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","id":17,"deviceId":0,"hypervisorType":"KVM"}},"diskSeq":0,"path":"3d9e6024-8aab-4a62-9823-68f5f4dea8c0","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"116.6.116.12","volumeSize":"21474836480"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"bb0dc5ef-0664-4885-b902-a7fc5560bf87","uuid":"8cf52f92-c697-4a7b-b21c-b8e1ed49b204","ip":"192.168.0.20","netmask":"255.255.255.0","gateway":"192.168.0.1","mac":"06:82:ae:00:00:20","dns1":"192.168.0.5","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabled":true}]},"wait":0}}]
}
2015-08-28 11:58:10,372 DEBUG [c.c.a.t.Request] (AgentManager-Handler-11:null)
Seq 1-2719892699955068952: Processing: { Ans: , MgmtId: 90520733719330, via:
1, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.PrepareForMigrationAnswer":{"result":true,"wait":0}}] }
2015-08-28 11:58:10,372 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) Seq
1-2719892699955068952: Received: { Ans: , MgmtId: 90520733719330, via: 1, Ver:
v1, Flags: 110, { PrepareForMigrationAnswer } }
2015-08-28 11:58:10,374 DEBUG [c.c.a.m.AgentAttache]
(AgentManager-Handler-11:null) Seq 1-2719892699955068952: No more commands found
2015-08-28 11:58:10,399 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) VM state
transitted from :Running to Migrating with event: MigrationRequestedvm's
original host id: 4 new host id: 1 host id before state transition: 4
2015-08-28 11:58:10,421 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) Hosts's actual
total CPU: 76832 and CPU after applying overprovisioning: 76832
2015-08-28 11:58:10,421 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) We are
allocating VM, increasing the used capacity of this host:1
2015-08-28 11:58:10,421 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) Current Used
CPU: 16500 , Free CPU:60332 ,Requested CPU: 1000
2015-08-28 11:58:10,421 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) Current Used
RAM: 17716740096 , Free RAM:49714814976 ,Requested RAM: 1073741824
2015-08-28 11:58:10,422 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) CPU STATS after
allocation: for host: 1, old used: 16500, old reserved: 0, actual total: 76832,
total with overprovisioning: 76832; new used:17500, reserved:0; requested
cpu:1000,alloc_from_last:false
2015-08-28 11:58:10,422 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) RAM STATS after
allocation: for host: 1, old used: 17716740096, old reserved: 0, total:
67431555072; new used: 18790481920, reserved: 0; requested mem:
1073741824,alloc_from_last:false
2015-08-28 11:58:10,471 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) Seq
4-1242993497154256920: Sending { Cmd , MgmtId: 90520733719330, via:
4(csca.dtscn.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.MigrateCommand":{"vmName":"i-2-13-VM","destIp":"116.6.116.16","hostGuid":"ea0ba9c0-4a34-3002-8550-87aa627b2e74-LibvirtComputingResource","isWindows":true,"vmTO":{"id":13,"name":"i-2-13-VM","type":"User","cpus":1,"minSpeed":1000,"maxSpeed":1000,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"Windows
Server 2008 R2 (64-bit)","platformEmulator":"Windows Server
2008","bootArgs":"","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"SkhNAKeuF7dyCiy4c94YXA==","params":{},"uuid":"4b4a6f98-e289-4157-b4e8-ac7952919499","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"3d9e6024-8aab-4a62-9823-68f5f4dea8c0","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"ffe66fef-cfe7-3257-9be4-a6fbc54dc6bf","id":1,"poolType":"NetworkFilesystem","host":"116.6.116.12","path":"/data/nfs/cs/jb/pri","port":2049,"url":"NetworkFilesystem://116.6.116.12/data/nfs/cs/jb/pri/?ROLE=Primary&STOREUUID=ffe66fef-cfe7-3257-9be4-a6fbc54dc6bf"}},"name":"ROOT-13","size":21474836480,"path":"3d9e6024-8aab-4a62-9823-68f5f4dea8c0","volumeId":17,"vmName":"i-2-13-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","id":17,"deviceId":0,"hypervisorType":"KVM"}},"diskSeq":0,"path":"3d9e6024-8aab-4a62-9823-68f5f4dea8c0","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"116.6.116.12","volumeSize":"21474836480"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"bb0dc5ef-0664-4885-b902-a7fc5560bf87","uuid":"8cf52f92-c697-4a7b-b21c-b8e1ed49b204","ip":"192.168.0.20","netmask":"255.255.255.0","gateway":"192.168.0.1","mac":"06:82:ae:00:00:20","dns1":"192.168.0.5","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabled":true}]},"executeInSequence":false,"wait":0}}]
}
2015-08-28 11:58:10,823 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-12:null) Ping from 3
2015-08-28 11:58:11,153 DEBUG [c.c.a.ApiServlet]
(catalina-exec-23:ctx-85711ee8) ===START=== 192.168.0.223 -- GET
command=queryAsyncJobResult&jobId=eb903d40-5ace-4f02-a860-662cfcb2b575&response=json&sessionkey=AbKJjZThFS2gUfobXgviVBM%2BwlI%3D&_=1440734287812
2015-08-28 11:58:11,183 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-13:null) Ping from 1
2015-08-28 11:58:11,184 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-13:null) Process host VM state report from ping process.
host: 1
2015-08-28 11:58:11,195 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-85711ee8
ctx-70ec2604) ===END=== 192.168.0.223 -- GET
command=queryAsyncJobResult&jobId=eb903d40-5ace-4f02-a860-662cfcb2b575&response=json&sessionkey=AbKJjZThFS2gUfobXgviVBM%2BwlI%3D&_=1440734287812
2015-08-28 11:58:11,205 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-13:null) Process VM state report. host: 1, number of
records in report: 3
2015-08-28 11:58:11,205 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-13:null) VM state report. host: 1, vm id: 7, power state:
PowerOn
2015-08-28 11:58:11,208 DEBUG [c.c.a.t.Request] (AgentManager-Handler-15:null)
Seq 4-1242993497154256920: Processing: { Ans: , MgmtId: 90520733719330, via:
4, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.MigrateAnswer":{"result":false,"details":"org.libvirt.LibvirtException:
internal error Process exited while reading console log output: Supported
machines are:\npc RHEL 6.5.0 PC (alias of rhel6.5.0)\nrhel6.5.0 RHEL
6.5.0 PC (default)\nrhel6.4.0 RHEL 6.4.0 PC\nrhel6.3.0 RHEL 6.3.0
PC\nrhel6.2.0 RHEL 6.2.0 PC\nrhel6.1.0 RHEL 6.1.0 PC\nrhel6.0.0 RHEL 6.0.0
PC\nrhel5.5.0 RHEL 5.5.0 PC\nrhel5.4.4 RHEL 5.4.4 PC\nrhel5.4.0 RHEL 5.4.0
PC\n","wait":0}}] }
2015-08-28 11:58:11,209 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) Seq
4-1242993497154256920: Received: { Ans: , MgmtId: 90520733719330, via: 4, Ver:
v1, Flags: 10, { MigrateAnswer } }
2015-08-28 11:58:11,209 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) Migration was
unsuccessful. Cleaning up: VM[User|i-2-13-VM]
2015-08-28 11:58:11,220 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-13:null) VM power state does not change, skip DB writing.
vm id: 7
2015-08-28 11:58:11,220 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-13:null) VM state report. host: 1, vm id: 8, power state:
PowerOn
2015-08-28 11:58:11,233 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-13:null) VM power state does not change, skip DB writing.
vm id: 8
2015-08-28 11:58:11,233 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-13:null) VM state report. host: 1, vm id: 9, power state:
PowerOn
2015-08-28 11:58:11,234 WARN [o.a.c.alerts] (Work-Job-Executor-2:ctx-5c8d315a
job-245/job-246 ctx-7e94b09d) alertType:: 17 // dataCenterId:: 1 // podId:: 1
// clusterId:: null // message:: Unable to migrate vm i-2-13-VM from host
csca.dtscn.com in zone JB and pod JB-POD
2015-08-28 11:58:11,242 DEBUG [c.c.a.AlertManagerImpl]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) Have already
sent: 1 emails for alert type '17' -- skipping send email
2015-08-28 11:58:11,244 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-13:null) VM power state does not change, skip DB writing.
vm id: 9
2015-08-28 11:58:11,245 DEBUG [c.c.a.m.AgentAttache]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) Seq
1-2719892699955068953: Routed from 90520733719330
2015-08-28 11:58:11,246 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) Seq
1-2719892699955068953: Sending { Cmd , MgmtId: 90520733719330, via:
1(cscb.dtscn.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-2-13-VM","wait":0}}]
}
2015-08-28 11:58:11,260 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-13:null) Done with process of VM state report. host: 1
2015-08-28 11:58:11,269 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) VM state
transitted from :Migrating to Running with event: OperationFailedvm's original
host id: 4 new host id: 4 host id before state transition: 1
2015-08-28 11:58:11,302 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) Hosts's actual
total CPU: 76832 and CPU after applying overprovisioning: 76832
2015-08-28 11:58:11,302 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) Hosts's actual
total RAM: 67431555072 and RAM after applying overprovisioning: 67431555072
2015-08-28 11:58:11,303 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) release cpu
from host: 1, old used: 17500,reserved: 0, actual total: 76832, total with
overprovisioning: 76832; new used: 16500,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2015-08-28 11:58:11,303 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) release mem
from host: 1, old used: 18790481920,reserved: 0, total: 67431555072; new used:
17716740096,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-08-28 11:58:11,327 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-2:ctx-5c8d315a job-245/job-246 ctx-7e94b09d) Invocation
exception, caused by: com.cloud.utils.exception.CloudRuntimeException:
org.libvirt.LibvirtException: internal error Process exited while reading
console log output: Supported machines are:
pc RHEL 6.5.0 PC (alias of rhel6.5.0)
rhel6.5.0 RHEL 6.5.0 PC (default)
rhel6.4.0 RHEL 6.4.0 PC
rhel6.3.0 RHEL 6.3.0 PC
rhel6.2.0 RHEL 6.2.0 PC
rhel6.1.0 RHEL 6.1.0 PC
rhel6.0.0 RHEL 6.0.0 PC
rhel5.5.0 RHEL 5.5.0 PC
rhel5.4.4 RHEL 5.4.4 PC
rhel5.4.0 RHEL 5.4.0 PC
