Moving this to dev, Mike. Probably more understanding of the matter
available there.
I don't understand the periode between 2015-05-08 09:58:13,766 until
2015-05-08 09:58:14,491
All of your log from the source host is between only two of the log entries
from the destination.
Can you maybe share the management log from the same attempt?
Op vr 8 mei 2015 om 18:13 schreef Daan Hoogland <daan.hoogl...@gmail.com>:
> H Mike, good to hear. I will have a look at it later this week end
>
> On Fri, 8 May 2015 16:02 Mike C <mcrosson_cloudst...@nusku.net> wrote:
>
>> On 2015-05-07 16:41, Daan Hoogland wrote:
>> > But if your patient I'll get there.
>> I'm here to see it through to the end ;) The good news is Remi's note
>> worked. I've included output below.
>>
>> On 2015-05-07 16:42, Remi Bergsma wrote:
>> > Hi Mike,
>> >
>> > Can you check if the agent has debug logging enabled in log4j.xml? If
>> > not, this enables it:
>> > sed -i 's/INFO/DEBUG/g' /etc/cloudstack/agent/log4j-cloud.xml
>> >
>> > Restart agent, then try again and we should see more logs.
>> I've included logs on both the "source agent" which is currently running
>> the VM and the "destination agent" which is the target of the migrate.
>>
>>
>>
>> =========================
>> ========== Source Agent
>> =========================
>> 2015-05-08 09:58:13,943 DEBUG [cloud.agent.Agent]
>> (agentRequest-Handler-5:null) Request:Seq 1-5821465468329787407: { Cmd
>> , MgmtId: 114374076129940, via: 1, Ver: v1, Flags: 100011,
>>
>> [{"com.cloud.agent.api.MigrateCommand":{"vmName":"r-93-VM","destIp":"172.16.16.31","hostGuid":"9a421209-fb8b-30ad-8304-95a4e33f3286-LibvirtComputingResource","isWindows":false,"vmTO":{"id":93,"name":"r-93-VM","type":"DomainRouter","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":268435456,"maxRam":268435456,"arch":"x86_64","os":"Debian
>> GNU/Linux
>>
>> 7(64-bit)","platformEmulator":"Other","bootArgs":"","rebootOnCrash":false,"enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"2b74e551cba07566","params":{},"uuid":"5269e919-564a-4986-92c1-07464e99e3ce","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"c1b45654-5e74-420e-bf91-5beb745546f8","volumeType":"ROOT","dataStore":{"org.
>> apache.cloudstack.storage.to
>> .PrimaryDataStoreTO":{"uuid":"d5174632-721e-39ed-b93b-462539f63c77","id":1,"poolType":"NetworkFilesystem","host":"172.16.16.25","path":"/srv/cloudstack/primary/0001","port":2049,"url":"NetworkFilesystem://
>> 172.16.16.25/srv/cloudstack/primary/0001/?ROLE=Primary&STOREUUID=d5174632-721e-39ed-b93b-462539f63c77
>> "}},"name":"ROOT-93","size":2621440000,"path":"c1b45654-5e74-420e-bf91-5beb745546f8","volumeId":132,"vmName":"r-93-VM","accountId":2,"format":"QCOW2","id":132,"deviceId":0,"cacheMode":"NONE","hypervisorType":"KVM"}},"diskSeq":0,"path":"c1b45654-5e74-420e-bf91-5beb745546f8","ty
>>
>> pe":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"172.16.16.25","volumeSize":"2621440000"}}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":false,"nicUuid":"3ae999b5-9d59-431a-a41b-7dbeb90c5509","uuid":"a011df28-a322-4d94-bf31-1f4fbb7a869b","ip":"172.16.18.1","netmask":"255.255.255.0","mac":"02:00:6b:5b:00:03","dns1":"172.16.17.2","dns2":"","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1209","isolationUri":"vlan://1209","isSecurityGroupEnabled":false,"name":"cloudbr1"},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"nicUuid":"cd17fc0c-164e-4fe8-acc0-36a13f37f5aa","uuid":"0e669946-5f4d-4c51-9b2e-564edc1dc06a","ip":"169.254.3.203","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:03:cb","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false},{"deviceId":2,"networkRateMbps":200,"defaultNic":true,"nicUuid":"9bc37269-68d5-40b8-ac08-4b60ccab5d0f","uuid":"80c92696-16cb-427e-855a-a2ac01c34ebc","i
>>
>> p":"172.16.17.202","netmask":"255.255.255.0","gateway":"172.16.17.2","mac":"06:13:ca:00:00:36","dns1":"172.16.17.2","dns2":"","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://untagged","isolationUri":"vlan://untagged","isSecurityGroupEnabled":false,"name":"cloudbr0"}]},"executeInSequence":false,"wait":0}}]
>> }
>> 2015-05-08 09:58:13,943 DEBUG [cloud.agent.Agent]
>> (agentRequest-Handler-5:null) Processing command:
>> com.cloud.agent.api.MigrateCommand
>> 2015-05-08 09:58:13,975 INFO [kvm.resource.LibvirtComputingResource]
>> (agentRequest-Handler-5:null) Live migration of instance r-93-VM
>> initiated
>> 2015-05-08 09:58:14,277 INFO [kvm.resource.LibvirtComputingResource]
>> (agentRequest-Handler-5:null) Migration thread for r-93-VM is done
>> 2015-05-08 09:58:14,278 DEBUG [kvm.resource.LibvirtComputingResource]
>> (agentRequest-Handler-5:null) Failed to execute while migrating domain:
>> org.libvirt.LibvirtException: Cannot get interface MTU on
>> 'brbond0-1209': No such device
>> 2015-05-08 09:58:14,290 DEBUG [cloud.agent.Agent]
>> (agentRequest-Handler-5:null) Seq 1-5821465468329787407: { Ans: ,
>> MgmtId: 114374076129940, via: 1, Ver: v1, Flags: 10,
>>
>> [{"com.cloud.agent.api.MigrateAnswer":{"result":false,"details":"org.libvirt.LibvirtException:
>> Cannot get interface MTU on 'brbond0-1209': No such device","wait":0}}]
>> }
>>
>>
>> =========================
>> ======= Destination Agent
>> =========================
>> 2015-05-08 09:58:13,766 DEBUG [cloud.agent.Agent]
>> (agentRequest-Handler-5:null) Request:Seq 18-630503947831869460: { Cmd
>> , MgmtId: 114374076129940, via: 18, Ver: v1, Flags: 100111,
>>
>> [{"com.cloud.agent.api.PrepareForMigrationCommand":{"vm":{"id":93,"name":"r-93-VM","type":"DomainRouter","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":268435456,"maxRam":268435456,"arch":"x86_64","os":"Debian
>> GNU/Linux
>>
>> 7(64-bit)","platformEmulator":"Other","bootArgs":"","rebootOnCrash":false,"enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"2b74e551cba07566","params":{},"uuid":"5269e919-564a-4986-92c1-07464e99e3ce","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"c1b45654-5e74-420e-bf91-5beb745546f8","volumeType":"ROOT","dataStore":{"org.
>> apache.cloudstack.storage.to
>> .PrimaryDataStoreTO":{"uuid":"d5174632-721e-39ed-b93b-462539f63c77","id":1,"poolType":"NetworkFilesystem","host":"172.16.16.25","path":"/srv/cloudstack/primary/0001","port":2049,"url":"NetworkFilesystem://
>> 172.16.16.25/srv/cloudstack/primary/0001/?ROLE=Primary&STOREUUID=d5174632-721e-39ed-b93b-462539f63c77
>> "}},"name":"ROOT-93","size":2621440000,"path":"c1b45654-5e74-420e-bf91-5beb745546f8","volumeId":132,"vmName":"r-93-VM","accountId":2,"format":"QCOW2","id":132,"deviceId":0,"cacheMode":"NONE","hypervisorType":"KVM"}},"diskSeq":0,"path":"c1b45654-5e74-420e-bf91-5beb745546f8","ty
>>
>> pe":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"172.16.16.25","volumeSize":"2621440000"}}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":false,"nicUuid":"3ae999b5-9d59-431a-a41b-7dbeb90c5509","uuid":"a011df28-a322-4d94-bf31-1f4fbb7a869b","ip":"172.16.18.1","netmask":"255.255.255.0","mac":"02:00:6b:5b:00:03","dns1":"172.16.17.2","dns2":"","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1209","isolationUri":"vlan://1209","isSecurityGroupEnabled":false,"name":"cloudbr1"},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"nicUuid":"cd17fc0c-164e-4fe8-acc0-36a13f37f5aa","uuid":"0e669946-5f4d-4c51-9b2e-564edc1dc06a","ip":"169.254.3.203","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:03:cb","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false},{"deviceId":2,"networkRateMbps":200,"defaultNic":true,"nicUuid":"9bc37269-68d5-40b8-ac08-4b60ccab5d0f","uuid":"80c92696-16cb-427e-855a-a2ac01c34ebc","i
>>
>> p":"172.16.17.202","netmask":"255.255.255.0","gateway":"172.16.17.2","mac":"06:13:ca:00:00:36","dns1":"172.16.17.2","dns2":"","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://untagged","isolationUri":"vlan://untagged","isSecurityGroupEnabled":false,"name":"cloudbr0"}]},"wait":0}}]
>> }
>> 2015-05-08 09:58:13,766 DEBUG [cloud.agent.Agent]
>> (agentRequest-Handler-5:null) Processing command:
>> com.cloud.agent.api.PrepareForMigrationCommand
>> 2015-05-08 09:58:13,766 DEBUG [kvm.resource.LibvirtComputingResource]
>> (agentRequest-Handler-5:null) Preparing host for migrating
>> com.cloud.agent.api.to.VirtualMachineTO@2a15bf12
>> 2015-05-08 09:58:13,769 DEBUG [kvm.resource.LibvirtConnection]
>> (agentRequest-Handler-5:null) can't find connection: KVM, for vm:
>> r-93-VM, continue
>> 2015-05-08 09:58:13,772 DEBUG [kvm.resource.LibvirtConnection]
>> (agentRequest-Handler-5:null) can't find connection: LXC, for vm:
>> r-93-VM, continue
>> 2015-05-08 09:58:13,772 DEBUG [kvm.resource.LibvirtConnection]
>> (agentRequest-Handler-5:null) can't find which hypervisor the vm used ,
>> then use the default hypervisor
>> 2015-05-08 09:58:13,774 DEBUG [kvm.resource.BridgeVifDriver]
>> (agentRequest-Handler-5:null) nic=[Nic:Guest-172.16.18.1-vlan://1209]
>> 2015-05-08 09:58:13,774 DEBUG [kvm.resource.BridgeVifDriver]
>> (agentRequest-Handler-5:null) creating a vNet dev and bridge for guest
>> traffic per traffic label cloudbr1
>> 2015-05-08 09:58:13,774 DEBUG [kvm.resource.BridgeVifDriver]
>> (agentRequest-Handler-5:null) Executing:
>> /usr/share/cloudstack-common/scripts/vm/network/vnet/modifyvlan.sh -v
>> 1209 -p eth0 -b breth0-1209 -o add
>> 2015-05-08 09:58:13,794 DEBUG [kvm.resource.BridgeVifDriver]
>> (agentRequest-Handler-5:null) Execution is successful.
>> 2015-05-08 09:58:13,795 DEBUG [kvm.resource.BridgeVifDriver]
>> (agentRequest-Handler-5:null) Set name-type for VLAN subsystem. Should
>> be visible in /proc/net/vlan/config
>>
>> 2015-05-08 09:58:13,796 DEBUG [kvm.resource.BridgeVifDriver]
>> (agentRequest-Handler-5:null) nic=[Nic:Control-169.254.3.203-null]
>> 2015-05-08 09:58:13,796 DEBUG [utils.script.Script]
>> (agentRequest-Handler-5:null) Executing: /bin/bash -c ip route | grep
>> 169.254.0.0/16
>> 2015-05-08 <http://169.254.0.0/162015-05-08> 09:58:13,802 DEBUG
>> [utils.script.Script]
>> (agentRequest-Handler-5:null) Execution is successful.
>> 2015-05-08 09:58:13,803 DEBUG [kvm.resource.BridgeVifDriver]
>> (agentRequest-Handler-5:null)
>> nic=[Nic:Public-172.16.17.202-vlan://untagged]
>> 2015-05-08 09:58:13,878 DEBUG [cloud.agent.Agent]
>> (agentRequest-Handler-5:null) Seq 18-630503947831869460: { Ans: ,
>> MgmtId: 114374076129940, via: 18, Ver: v1, Flags: 110,
>>
>> [{"com.cloud.agent.api.PrepareForMigrationAnswer":{"result":true,"wait":0}}]
>> }
>> 2015-05-08 09:58:14,305 DEBUG [cloud.agent.Agent]
>> (agentRequest-Handler-1:null) Request:Seq 18-630503947831869461: { Cmd
>> , MgmtId: 114374076129940, via: 18, Ver: v1, Flags: 100011,
>>
>> [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"r-93-VM","wait":0}}]
>> }
>> 2015-05-08 09:58:14,306 DEBUG [cloud.agent.Agent]
>> (agentRequest-Handler-1:null) Processing command:
>> com.cloud.agent.api.StopCommand
>> 2015-05-08 09:58:14,309 DEBUG [kvm.resource.LibvirtConnection]
>> (agentRequest-Handler-1:null) can't find connection: KVM, for vm:
>> r-93-VM, continue
>> 2015-05-08 09:58:14,312 DEBUG [kvm.resource.LibvirtConnection]
>> (agentRequest-Handler-1:null) can't find connection: LXC, for vm:
>> r-93-VM, continue
>> 2015-05-08 09:58:14,312 DEBUG [kvm.resource.LibvirtConnection]
>> (agentRequest-Handler-1:null) can't find which hypervisor the vm used ,
>> then use the default hypervisor
>> 2015-05-08 09:58:14,316 DEBUG [kvm.resource.LibvirtComputingResource]
>> (agentRequest-Handler-1:null) Failed to get dom xml:
>> org.libvirt.LibvirtException: Domain not found: no domain with matching
>> name 'r-93-VM'
>> 2015-05-08 09:58:14,318 DEBUG [kvm.resource.LibvirtComputingResource]
>> (agentRequest-Handler-1:null) Failed to get dom xml:
>> org.libvirt.LibvirtException: Domain not found: no domain with matching
>> name 'r-93-VM'
>> 2015-05-08 09:58:14,322 DEBUG [kvm.resource.LibvirtComputingResource]
>> (agentRequest-Handler-1:null) Failed to get dom xml:
>> org.libvirt.LibvirtException: Domain not found: no domain with matching
>> name 'r-93-VM'
>> 2015-05-08 09:58:14,322 DEBUG [kvm.resource.LibvirtComputingResource]
>> (agentRequest-Handler-1:null) Executing:
>> /usr/share/cloudstack-common/scripts/vm/network/security_group.py
>> destroy_network_rules_for_vm --vmname r-93-VM
>> 2015-05-08 09:58:14,485 DEBUG [kvm.resource.LibvirtComputingResource]
>> (agentRequest-Handler-1:null) Execution is successful.
>> 2015-05-08 09:58:14,487 DEBUG [kvm.resource.LibvirtComputingResource]
>> (agentRequest-Handler-1:null) Try to stop the vm at first
>> 2015-05-08 09:58:14,490 DEBUG [kvm.resource.LibvirtComputingResource]
>> (agentRequest-Handler-1:null) VM r-93-VM doesn't exist, no need to stop
>> it
>> 2015-05-08 09:58:14,491 DEBUG [cloud.agent.Agent]
>> (agentRequest-Handler-1:null) Seq 18-630503947831869461: { Ans: ,
>> MgmtId: 114374076129940, via: 18, Ver: v1, Flags: 10,
>> [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
>> 2015-05-08 09:58:56,341 DEBUG [kvm.resource.KVMHAMonitor]
>> (Thread-6:null) Found NFS storage pool
>> d5174632-721e-39ed-b93b-462539f63c77 in libvirt, continuing
>>
>
