You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cloudstack.apache.org by Alex Lee <al...@orbistechnologies.com> on 2014/03/18 18:29:32 UTC

Communication issues between primary storage and secondary storage

Hello,

We are currently working with Cloudstack 4.0.2 on a single zone/pod/cluster setup with 4 hosts (CentOS 6, KVM)and one storage appliance (FreeNAS) serving as primary storage and secondary storage. We recently experienced problems with our system's primary storage's file system to the point that we needed to rebuild it. We've also had to replace our secondary storage by creating a new NFS share that we've re-imported all of our templates and ISOs to. With all of these changes, we've recreated the SSVM multiple times to reflect the new Secondary Storage settings.

The issue that we're currently experiencing is that data from Secondary Storage doesn't seem to be able to transfer to Primary Storage. When we try to create a VM from a template, the creation fails. The errors seen in management.log are the first group of logs below.

With this failed attempt, the database table template_spool_ref adds a row with the correct  template_id, but with the download_pct=0 and state="NOT DOWNLOADED". We encountered a similar issue even just getting the System VM template onto Secondary Storage with the included script, where the template is added to secondary storage, but the database and primary storage do not reflect it being cached locally in /mnt/primary. We had to manually copy the System VM Template to /mnt/primary and rename it to what the database expected to be in /mnt/primary just to get our Secondary Storage VM to be created.

We are unable to create VMs from ISOs as well, reinforcing the notion that there is an issue with accessing Secondary Storage. These errors are in the second group of logs below. Attaching an ISO to a working  VM also makes it unable to start.

However, when accessing the SSVM, we can see that our single Secondary Storage is successfully mounted and accessible at /mnt/SecStorage/41a329bb-e5aa-3e98-892f-d5cfb582114c. ssvm-check.sh also reveals no errors. The machine hosting Secondary storage is also able to successfully ping the SSVM, and all files and directories have 777 permissions.

At this point, our suspicion is that there is an issue with bringing templates/ISOs from Secondary Storage down to primary storage, but we have no idea what could be causing it. Any and all help would be greatly appreciated.

Thanks in advance,

Alex Lee


Errors when creating VM from template:

2014-03-18 12:50:01,486 DEBUG [agent.manager.AgentManagerImpl] (Job-Executor-116:job-554) Details from executing class com.cloud.agent.api.storage.PrimaryStorageDownloadCommand: com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Storage volume not found: no storage vol with matching name 'd8934d71-65b4-3a64-ad4d-f1c1605637d2.qcow2'
2014-03-18 12:50:01,486 DEBUG [cloud.template.TemplateManagerImpl] (Job-Executor-116:job-554) Template 337 download to pool 206 failed due to com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Storage volume not found: no storage vol with matching name 'd8934d71-65b4-3a64-ad4d-f1c1605637d2.qcow2'
2014-03-18 12:50:01,486 DEBUG [cloud.template.TemplateManagerImpl] (Job-Executor-116:job-554) Downloading 337 via 1
2014-03-18 12:50:01,490 DEBUG [agent.transport.Request] (Job-Executor-116:job-554) Seq 1-890971889: Sending  { Cmd , MgmtId: 161331456390, via: 1, Ver: v1, Flags: 100111, [{"storage.PrimaryStorageDownloadCommand":{"localPath":"/mnt/fd7aa037-9a5c-38fe-8e22-e454debe78f0","poolUuid":"53698317-909d-4caf-b383-0b1056a67152","poolId":206,"secondaryStorageUrl":"nfs://san01.aitecd.us.gov/mnt/U1Volume/secondaryStorage","primaryStorageUrl":"nfs://localhost/mnt/primary","url":"nfs://san01.aitecd.us.gov/mnt/U1Volume/secondaryStorage/template/tmpl//2/337//d8934d71-65b4-3a64-ad4d-f1c1605637d2.qcow2","format":"QCOW2","accountId":2,"name":"337-2-3904c94e-83a6-3f00-a2aa-e3f28168cab2","wait":10800}}] }
2014-03-18 12:50:01,610 DEBUG [agent.transport.Request] (AgentManager-Handler-7:null) Seq 1-890971889: Processing:  { Ans: , MgmtId: 161331456390, via: 1, Ver: v1, Flags: 110, [{"storage.PrimaryStorageDownloadAnswer":{"templateSize":0,"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Storage volume not found: no storage vol with matching name 'd8934d71-65b4-3a64-ad4d-f1c1605637d2.qcow2'","wait":0}}] }
2014-03-18 12:50:01,610 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-7:null) Seq 1-890971889: No more commands found
2014-03-18 12:50:01,610 DEBUG [agent.transport.Request] (Job-Executor-116:job-554) Seq 1-890971889: Received:  { Ans: , MgmtId: 161331456390, via: 1, Ver: v1, Flags: 110, { PrimaryStorageDownloadAnswer } }
2014-03-18 12:50:01,610 DEBUG [agent.manager.AgentManagerImpl] (Job-Executor-116:job-554) Details from executing class com.cloud.agent.api.storage.PrimaryStorageDownloadCommand: com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Storage volume not found: no storage vol with matching name 'd8934d71-65b4-3a64-ad4d-f1c1605637d2.qcow2'
2014-03-18 12:50:01,610 DEBUG [cloud.template.TemplateManagerImpl] (Job-Executor-116:job-554) Template 337 download to pool 206 failed due to com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Storage volume not found: no storage vol with matching name 'd8934d71-65b4-3a64-ad4d-f1c1605637d2.qcow2'
2014-03-18 12:50:01,611 DEBUG [cloud.template.TemplateManagerImpl] (Job-Executor-116:job-554) Template 337 is not found on and can not be downloaded to pool 206
2014-03-18 12:50:01,611 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-116:job-554) Cannot use this pool Pool[206|SharedMountPoint] because we can't propagate template Tmpl[337-QCOW2-337-2-3904c94e-83a6-3f00-a2aa-e3f28168cab2
2014-03-18 12:50:01,617 INFO  [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-116:job-554) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:206] is unreachable: Unable to create Vol[1344|vm=1240|ROOT]
        at com.cloud.storage.StorageManagerImpl.prepare(StorageManagerImpl.java:3361)
        at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:754)
        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:2601)
        at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2589)
        at com.cloud.event.ActionEventCallback.intercept(ActionEventCallback.java:36)
        at com.cloud.api.commands.DeployVMCmd.execute(DeployVMCmd.java:330)
        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:1146)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:679)

Errors when creating VM with ISO:

2014-03-18 13:20:30,139 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Asking Ovs to prepare for Nic[4007-1241-7fff009b-a5f8-48a4-8452-94d386853820-172.16.42.85]
2014-03-18 13:20:30,139 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Asking ExternalDhcpServer to prepare for Nic[4007-1241-7fff009b-a5f8-48a4-8452-94d386853820-172.16.42.85]
2014-03-18 13:20:30,141 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Asking BareMetal to prepare for Nic[4007-1241-7fff009b-a5f8-48a4-8452-94d386853820-172.16.42.85]
2014-03-18 13:20:30,141 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Asking SecurityGroupProvider to prepare for Nic[4007-1241-7fff009b-a5f8-48a4-8452-94d386853820-172.16.42.85]
2014-03-18 13:20:30,144 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Asking CiscoNexus1000vVSM to prepare for Nic[4007-1241-7fff009b-a5f8-48a4-8452-94d386853820-172.16.42.85]
2014-03-18 13:20:30,144 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Asking VpcVirtualRouter to prepare for Nic[4007-1241-7fff009b-a5f8-48a4-8452-94d386853820-172.16.42.85]
2014-03-18 13:20:30,144 WARN  [network.element.VpcVirtualRouterElement] (Job-Executor-119:job-557) Network Ntwk[204|Guest|6] is not associated with any VPC
2014-03-18 13:20:30,149 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Asking NiciraNvp to prepare for Nic[4007-1241-7fff009b-a5f8-48a4-8452-94d386853820-172.16.42.85]
2014-03-18 13:20:30,155 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-119:job-557) Checking if we need to prepare 1 volumes for VM[User|dc-new]
2014-03-18 13:20:30,160 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-119:job-557) Creating volume: Vol[1345|vm=1241|ROOT]
2014-03-18 13:20:30,160 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-119:job-557) Trying to create in Pool[206|SharedMountPoint]
2014-03-18 13:20:30,167 DEBUG [agent.transport.Request] (Job-Executor-119:job-557) Seq 10-328016044: Sending  { Cmd , MgmtId: 161331456390, via: 10, Ver: v1, Flags: 100111, [{"storage.CreateCommand":{"volId":1345,"pool":{"id":206,"uuid":"53698317-909d-4caf-b383-0b1056a67152","host":"localhost","path":"/mnt/primary","port":0,"type":"SharedMountPoint"},"diskCharacteristics":{"size":53687091200,"tags":[],"type":"ROOT","name":"ROOT-1241","useLocalStorage":false,"recreatable":false,"diskOfferingId":44,"volumeId":1345,"hyperType":"KVM"},"wait":0}}] }
2014-03-18 13:20:30,469 DEBUG [agent.transport.Request] (AgentManager-Handler-3:null) Seq 10-328016044: Processing:  { Ans: , MgmtId: 161331456390, via: 10, Ver: v1, Flags: 110, [{"storage.CreateAnswer":{"volume":{"id":1345,"name":"/mnt/primary","mountPoint":"e2b921f9-801a-43ad-af3e-6ab1b9c042ea","path":"e2b921f9-801a-43ad-af3e-6ab1b9c042ea","size":53687091200,"type":"ROOT","storagePoolType":"SharedMountPoint","storagePoolUuid":"53698317-909d-4caf-b383-0b1056a67152","deviceId":0},"requestTemplateReload":false,"result":true,"wait":0}}] }
2014-03-18 13:20:30,469 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-3:null) Seq 10-328016044: No more commands found
2014-03-18 13:20:30,470 DEBUG [agent.transport.Request] (Job-Executor-119:job-557) Seq 10-328016044: Received:  { Ans: , MgmtId: 161331456390, via: 10, Ver: v1, Flags: 110, { CreateAnswer } }
2014-03-18 13:20:30,475 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-119:job-557) Volume Vol[1345|vm=1241|ROOT] is created on Pool[206|SharedMountPoint]
2014-03-18 13:20:30,489 DEBUG [agent.transport.Request] (Job-Executor-119:job-557) Seq 10-328016045: Sending  { Cmd , MgmtId: 161331456390, via: 10, Ver: v1, Flags: 100111, [{"StartCommand":{"vm":{"id":1241,"name":"i-2-1241-VM","type":"User","cpus":1,"speed":2000,"minRam":2147483648,"maxRam":2147483648,"arch":"x86_64","os":"Windows Server 2008 R2 (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":true,"limitCpuUse":false,"vncPassword":"a4b6257af0c390fe","params":{},"uuid":"c718d3fe-965e-4a7d-aad4-6409ccbb3f56","disks":[{"id":1345,"name":"/mnt/primary","mountPoint":"e2b921f9-801a-43ad-af3e-6ab1b9c042ea","path":"e2b921f9-801a-43ad-af3e-6ab1b9c042ea","size":53687091200,"type":"ROOT","storagePoolType":"SharedMountPoint","storagePoolUuid":"53698317-909d-4caf-b383-0b1056a67152","deviceId":0},{"id":1241,"name":"Windows Server 2008 AGM","path":"nfs://san01.aitecd.us.gov/mnt/U1Volume/secondaryStorage/template/tmpl//2/331//331-2-b6d4b70d-fa70-3937-838b-f07e52da2283.iso","size":0,"type":"ISO","storagePoolType":"ISO","deviceId":3,"guestOsType":"Windows Server 2008 R2 (64-bit)"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"d7d19741-47b5-4f89-b73f-fa42163e2d00","ip":"172.16.42.85","netmask":"255.255.0.0","gateway":"172.16.42.1","mac":"06:e8:ec:00:00:4a","dns1":"172.16.42.69","dns2":"172.16.42.70","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":false}]},"wait":0}}] }
2014-03-18 13:20:30,562 DEBUG [agent.transport.Request] (AgentManager-Handler-11:null) Seq 10-328016045: Processing:  { Ans: , MgmtId: 161331456390, via: 10, Ver: v1, Flags: 110, [{"Answer":{"result":false,"details":"java.lang.NullPointerException\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.cleanupVMNetworks(LibvirtComputingResource.java:3943)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.handleVmStartFailure(LibvirtComputingResource.java:2730)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:2855)\n\tat com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1061)\n\tat com.cloud.agent.Agent.processRequest(Agent.java:518)\n\tat com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:831)\n\tat com.cloud.utils.nio.Task.run(Task.java:83)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tat java.lang.Thread.run(Thread.java:679)\n","wait":0}}] }
2014-03-18 13:20:30,562 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-11:null) Seq 10-328016045: No more commands found
2014-03-18 13:20:30,562 DEBUG [agent.transport.Request] (Job-Executor-119:job-557) Seq 10-328016045: Received:  { Ans: , MgmtId: 161331456390, via: 10, Ver: v1, Flags: 110, { Answer } }
2014-03-18 13:20:30,567 ERROR [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-119:job-557) Failed to start instance VM[User|dc-new]
com.cloud.utils.exception.CloudRuntimeException: Unable to get answer that is of class com.cloud.agent.api.StartAnswer
        at com.cloud.agent.manager.Commands.getAnswer(Commands.java:80)
        at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:783)
        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:2601)
        at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2589)
        at com.cloud.event.ActionEventCallback.intercept(ActionEventCallback.java:36)
        at com.cloud.api.commands.DeployVMCmd.execute(DeployVMCmd.java:330)
        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:1146)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:679)
2014-03-18 13:20:30,572 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-119:job-557) Cleaning up resources for the vm VM[User|dc-new] in Starting state
2014-03-18 13:20:30,573 DEBUG [agent.transport.Request] (Job-Executor-119:job-557) Seq 10-328016046: Sending  { Cmd , MgmtId: 161331456390, via: 10, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-1241-VM","wait":0}}] }
2014-03-18 13:20:30,783 DEBUG [agent.transport.Request] (AgentManager-Handler-15:null) Seq 10-328016046: Processing:  { Ans: , MgmtId: 161331456390, via: 10, Ver: v1, Flags: 110, [{"StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2014-03-18 13:20:30,783 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-15:null) Seq 10-328016046: No more commands found
2014-03-18 13:20:30,783 DEBUG [agent.transport.Request] (Job-Executor-119:job-557) Seq 10-328016046: Received:  { Ans: , MgmtId: 161331456390, via: 10, Ver: v1, Flags: 110, { StopAnswer } }
2014-03-18 13:20:30,795 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Changing active number of nics for network id=204 on -1
2014-03-18 13:20:30,799 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Asking JuniperSRX to release Nic[4007-1241-7fff009b-a5f8-48a4-8452-94d386853820-172.16.42.85]
2014-03-18 13:20:30,799 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Asking Netscaler to release Nic[4007-1241-7fff009b-a5f8-48a4-8452-94d386853820-172.16.42.85]
2014-03-18 13:20:30,799 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Asking F5BigIP to release Nic[4007-1241-7fff009b-a5f8-48a4-8452-94d386853820-172.16.42.85]
2014-03-18 13:20:30,799 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Asking VirtualRouter to release Nic[4007-1241-7fff009b-a5f8-48a4-8452-94d386853820-172.16.42.85]
2014-03-18 13:20:30,799 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Asking Ovs to release Nic[4007-1241-7fff009b-a5f8-48a4-8452-94d386853820-172.16.42.85]
2014-03-18 13:20:30,799 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Asking ExternalDhcpServer to release Nic[4007-1241-7fff009b-a5f8-48a4-8452-94d386853820-172.16.42.85]
2014-03-18 13:20:30,799 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Asking BareMetal to release Nic[4007-1241-7fff009b-a5f8-48a4-8452-94d386853820-172.16.42.85]
2014-03-18 13:20:30,799 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Asking SecurityGroupProvider to release Nic[4007-1241-7fff009b-a5f8-48a4-8452-94d386853820-172.16.42.85]
2014-03-18 13:20:30,799 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Asking CiscoNexus1000vVSM to release Nic[4007-1241-7fff009b-a5f8-48a4-8452-94d386853820-172.16.42.85]
2014-03-18 13:20:30,799 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Asking VpcVirtualRouter to release Nic[4007-1241-7fff009b-a5f8-48a4-8452-94d386853820-172.16.42.85]
2014-03-18 13:20:30,799 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-119:job-557) Asking NiciraNvp to release Nic[4007-1241-7fff009b-a5f8-48a4-8452-94d386853820-172.16.42.85]
2014-03-18 13:20:30,799 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-119:job-557) Successfully released network resources for the vm VM[User|dc-new]
2014-03-18 13:20:30,799 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-119:job-557) Successfully cleanued up resources for the vm VM[User|dc-new] in Starting state
2014-03-18 13:20:30,808 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-119:job-557) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 10
2014-03-18 13:20:30,811 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-119:job-557) Hosts's actual total CPU: 57600 and CPU after applying overprovisioning: 57600
2014-03-18 13:20:30,811 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-119:job-557) release cpu from host: 10, old used: 6100,reserved: 0, actual total: 57600, total with overprovisioning: 57600; new used: 4100,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-03-18 13:20:30,811 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-119:job-557) release mem from host: 10, old used: 7516192768,reserved: 0, total: 203097681920; new used: 5368709120,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-03-18 13:20:30,816 DEBUG [cloud.vm.UserVmManagerImpl] (Job-Executor-119:job-557) Destroying vm VM[User|dc-new] as it failed to create
2014-03-18 13:20:30,826 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-119:job-557) VM state transitted from :Stopped to Error with event: OperationFailedToErrorvm's original host id: null new host id: null host id before state transition: null
2014-03-18 13:20:30,865 WARN  [api.commands.DeployVMCmd] (Job-Executor-119:job-557) Exception:
com.cloud.exception.AgentUnavailableException: Resource [Host:10] is unreachable: Host 10: Unable to start instance due to Unable to get answer that is of class com.cloud.agent.api.StartAnswer
        at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:847)
        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:2601)
        at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2589)
        at com.cloud.event.ActionEventCallback.intercept(ActionEventCallback.java:36)
        at com.cloud.api.commands.DeployVMCmd.execute(DeployVMCmd.java:330)
        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:1146)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:679)
Caused by: com.cloud.utils.exception.CloudRuntimeException: Unable to get answer that is of class com.cloud.agent.api.StartAnswer
        at com.cloud.agent.manager.Commands.getAnswer(Commands.java:80)
        at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:783)
        ... 18 more