Hello,
I was building a Instance when a KVM host crashed, I can't find an error in
the logs.
I am attaching log file from management server
Thanks,
2014-04-03 11:32:22,218 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null)
===START=== -- GET
command=deployVirtualMachine&zoneId=9e6ddfd8-35ed-4c10-91fe-6b989b4c6f02&templateId=92e18994-dc75-4165-b7db-dfdb4cdb8f6b&hypervisor=KVM&serviceOfferingId=e34b15bf-b521-4809-9b50-de08e8a3a953&networkIds=a0aa07a9-d3aa-4da3-8971-81e0ac530bb4&displayname=IISBACK7&name=IISBACK7&response=json&sessionkey=H5y5UkJ5Ta6QlE0sePQeHrM8ks8%3D&_=1396549942376
2014-04-03 11:32:22,425 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-3:null) Allocating entries for VM: VM[User|IISBACK7]
2014-04-03 11:32:22,426 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-3:null) Allocating nics for VM[User|IISBACK7]
2014-04-03 11:32:22,427 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-3:null) Allocating nic for vm VM[User|IISBACK7] in network
Ntwk[231|Guest|30] with requested profile NicProfile[0-0-null-null-null
2014-04-03 11:32:22,516 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-3:null) Allocating disks for VM[User|IISBACK7]
2014-04-03 11:32:22,527 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(catalina-exec-3:null) Allocation completed for VM: VM[User|IISBACK7]
2014-04-03 11:32:22,527 DEBUG [cloud.vm.UserVmManagerImpl]
(catalina-exec-3:null) Successfully allocated DB entry for VM[User|IISBACK7]
2014-04-03 11:32:22,872 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-3:null) submit async job-1537 = [
3376ad95-e870-4db0-97f0-04c6294bf75d ], details: AsyncJobVO {id:1537, userId:
2, accountId: 2, sessionKey: null, instanceType: VirtualMachine, instanceId:
193, cmd: org.apache.cloudstack.api.command.user.vm.DeployVMCmd, cmdOriginator:
null, cmdInfo:
{"sessionkey":"H5y5UkJ5Ta6QlE0sePQeHrM8ks8\u003d","cmdEventType":"VM.CREATE","ctxUserId":"2","serviceOfferingId":"e34b15bf-b521-4809-9b50-de08e8a3a953","httpmethod":"GET","zoneId":"9e6ddfd8-35ed-4c10-91fe-6b989b4c6f02","templateId":"92e18994-dc75-4165-b7db-dfdb4cdb8f6b","response":"json","id":"193","networkIds":"a0aa07a9-d3aa-4da3-8971-81e0ac530bb4","hypervisor":"KVM","name":"IISBACK7","_":"1396549942376","ctxAccountId":"2","ctxStartEventId":"5836","displayname":"IISBACK7"},
cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
processStatus: 0, resultCode: 0, result: null, initMsid: 113348971808,
completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2014-04-03 11:32:22,873 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null)
===END=== -- GET
command=deployVirtualMachine&zoneId=9e6ddfd8-35ed-4c10-91fe-6b989b4c6f02&templateId=92e18994-dc75-4165-b7db-dfdb4cdb8f6b&hypervisor=KVM&serviceOfferingId=e34b15bf-b521-4809-9b50-de08e8a3a953&networkIds=a0aa07a9-d3aa-4da3-8971-81e0ac530bb4&displayname=IISBACK7&name=IISBACK7&response=json&sessionkey=H5y5UkJ5Ta6QlE0sePQeHrM8ks8%3D&_=1396549942376
2014-04-03 11:32:23,224 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c6294bf75d ])
Successfully transitioned to start state for VM[User|IISBACK7] reservation id =
1ad767a7-3be2-4dbe-ac8d-78fee67d99bf
2014-04-03 11:32:23,450 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4d
b0-97f0-04c6294bf75d ]) Deployment found - P0=VM[User|IISBACK7],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-S
torage(Volume(Id|Type-->Pool(Id))] :
Dest[Zone(5)-Pod(5)-Cluster(5)-Host(23)-Storage(Volume(224|ROOT-->Pool(15))]
2014-04-03 11:32:24,042 DEBUG [agent.transport.Request]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c
6294bf75d ]) Seq 23-787453337: Sending { Cmd , MgmtId: 113348971808, via: 23,
Ver: v1, Flags: 100111, [{"com.clo
ud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:69:58:00:1a","vmIpAddress":"10.75.0.220","vmName":"IISBACK
7","defaultRouter":"10.75.0.1","duid":"00:03:00:01:02:00:69:58:00:1a","isDefault":true,"executeInSequence":true,"
accessDetails":{"router.guest.ip":"10.75.0.170","zone.network.type":"Advanced","router.name":"r-119-VM","router.i
p":"169.254.3.226"},"wait":0}}] }
2014-04-03 11:32:24,860 DEBUG [agent.transport.Request]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c6294bf75d ]) Seq
28-1971685772: Sending { Cmd , MgmtId: 113348971808, via: 28, Ver: v1, Flags:
100111,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:69:58:00:1a","vmIpAddress":"10.75.0.220","vmName":"IISBACK7","defaultRouter":"10.75.0.1","duid":"00:03:00:01:02:00:69:58:00:1a","isDefault":true,"executeInSequence":true,"accessDetails":{"router.guest.ip":"10.75.0.153","zone.network.type":"Advanced","router.name":"r-120-VM","router.ip":"169.254.2.219"},"wait":0}}]
}
2014-04-03 11:32:25,804 DEBUG [agent.transport.Request]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c6294bf75d ]) Seq
23-787453340: Sending { Cmd , MgmtId: 113348971808, via: 23, Ver: v1, Flags:
100111,
[{"com.cloud.agent.api.routing.SavePasswordCommand":{"password":"fnirq_cnffjbeq","vmIpAddress":"10.75.0.220","vmName":"IISBACK7","executeInSequence":true,"accessDetails":{"router.guest.ip":"10.75.0.170","zone.network.type":"Advanced","router.ip":"169.254.3.226","router.name":"r-119-VM"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.75.0.220","vmName":"IISBACK7","executeInSequence":true,"accessDetails":{"router.guest.ip":"10.75.0.170","zone.network.type":"Advanced","router.ip":"169.254.3.226","router.name":"r-119-VM"},"wait":0}}]
}
2014-04-03 11:32:27,459 DEBUG [agent.transport.Request]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c6294bf75d ]) Seq
28-1971685774: Sending { Cmd , MgmtId: 113348971808, via: 28, Ver: v1, Flags:
100111,
[{"com.cloud.agent.api.routing.SavePasswordCommand":{"password":"fnirq_cnffjbeq","vmIpAddress":"10.75.0.220","vmName":"IISBACK7","executeInSequence":true,"accessDetails":{"router.guest.ip":"10.75.0.153","zone.network.type":"Advanced","router.ip":"169.254.2.219","router.name":"r-120-VM"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.75.0.220","vmName":"IISBACK7","executeInSequence":true,"accessDetails":{"router.guest.ip":"10.75.0.153","zone.network.type":"Advanced","router.ip":"169.254.2.219","router.name":"r-120-VM"},"wait":0}}]
}
2014-04-03 11:32:28,878 DEBUG [cloud.storage.VolumeManagerImpl]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c6294bf75d ]) Checking
if we need to prepare 1 volumes for VM[User|IISBACK7]
2014-04-03 12:02:49,523 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c6294bf75d ])
Determining why we're unable to update the state to Starting for
VM[User|IISBACK7]. Retry=4i
2014-04-03 12:04:49,525 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c6294bf75d ]) Waiting
some more to make sure there's no activity on VM[User|IISBACK7]
2014-04-03 12:06:49,526 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c6294bf75d ]) Waiting
some more to make sure there's no activity on VM[User|IISBACK7]
2014-04-03 12:08:49,528 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c6294bf75d ]) Waiting
some more to make sure there's no activity on VM[User|IISBACK7]
2014-04-03 12:10:49,529 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c6294bf75d ]) Waiting
some more to make sure there's no activity on VM[User|IISBACK7]
2014-04-03 12:12:49,531 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c6294bf75d ]) Waiting
some more to make sure there's no activity on VM[User|IISBACK7]
2014-04-03 12:14:45,398 DEBUG [cloud.ha.HighAvailabilityManagerImpl]
(AgentConnectTaskPool-30:null) VM does not require investigation so I'm marking
it as Stopped: VM[User|IISBACK7]
2014-04-03 12:14:45,399 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentConnectTaskPool-30:null) Found an outstanding work item for this vm
VM[User|IISBACK7] with state:Starting, work
id:1ad767a7-3be2-4dbe-ac8d-78fee67d99bf
2014-04-03 12:14:45,400 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentConnectTaskPool-30:null) Cleaning up resources for the vm
VM[User|IISBACK7] in Starting state
2014-04-03 12:14:45,633 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentConnectTaskPool-30:null) Successfully released network resources for the
vm VM[User|IISBACK7]
2014-04-03 12:14:45,633 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentConnectTaskPool-30:null) Successfully cleanued up resources for the vm
VM[User|IISBACK7] in Starting state
2014-04-03 12:14:47,048 INFO [cloud.ha.HighAvailabilityManagerImpl]
(AgentConnectTaskPool-30:null) Schedule vm for HA: VM[User|IISBACK7]
2014-04-03 12:14:49,532 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c6294bf75d ]) Waiting
some more to make sure there's no activity on VM[User|IISBACK7]
2014-04-03 12:14:49,533 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c6294bf75d ]) Unable to
find work for VM: VM[User|IISBACK7] and state: Starting
2014-04-03 12:14:49,537 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c6294bf75d ])
Determining why we're unable to update the state to Starting for
VM[User|IISBACK7]. Retry=3
2014-04-03 12:14:49,540 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c6294bf75d ])
Determining why we're unable to update the state to Starting for
VM[User|IISBACK7]. Retry=2
2014-04-03 12:14:49,543 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c6294bf75d ])
Determining why we're unable to update the state to Starting for
VM[User|IISBACK7]. Retry=1
2014-04-03 12:14:49,546 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c6294bf75d ])
Determining why we're unable to update the state to Starting for
VM[User|IISBACK7]. Retry=0
2014-04-03 12:14:49,547 DEBUG [cloud.vm.UserVmManagerImpl]
(Job-Executor-64:job-1537 = [ 3376ad95-e870-4db0-97f0-04c6294bf75d ])
Destroying vm VM[User|IISBACK7] as it failed to create on Host with Id:null
Caused by: com.cloud.exception.ConcurrentOperationException: Unable to change
the state of VM[User|IISBACK7]
2014-04-03 12:15:31,841 INFO [cloud.ha.HighAvailabilityManagerImpl]
(HA-Worker-0:work-111) HA on VM[User|IISBACK7]
2014-04-03 12:15:31,841 INFO [cloud.ha.HighAvailabilityManagerImpl]
(HA-Worker-0:work-111) VM VM[User|IISBACK7] has been changed. Current State =
Error Previous State = Stopped last updated = 4 previous updated = 3
