You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users-cn@cloudstack.apache.org by xool <17...@qq.com> on 2015/08/28 09:17:05 UTC
cloudstack4.5 迁移失败，附日志，请高人看看
环境：
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