[ovirt-users] Migration of VM fails Failed in 'DestroyVDS' method Message: VDSM command failed: Virtual machine does not exist
Tomas Jelinek
tjelinek at redhat.com
Mon Dec 21 11:35:28 UTC 2015
Hey Johann,
I think this is not an actual bug but a general issue with the migration convergence + a general problem with reported error messages
during migrations (both are being worked on and targeted to 4.0).
In your particular case the root cause seems like this from logs:
"The migration took 40 seconds which is exceeding the configured maximum time for migrations of 32 s
econds. The migration will be aborted."
So I'd say the VM was able to trash the memory faster than being moved to destination and after 40s it was aborted.
What you can do is to go to the vdsm.conf on each host and tweak migration progress timeout, migration bandwidth (if you have capacity for more than 32 MBps on the migration network per VM) and maybe max migration downtime (the time how long the VM can be paused at the end of migration).
Also from inside of the guest you can try to reduce the load if possible so it will not trash the memory so fast...
hope some of this helps,
Tomas
----- Original Message -----
> From: "Johann Kiefel" <info at dshin.net>
> To: users at ovirt.org
> Sent: Thursday, December 17, 2015 4:32:36 PM
> Subject: [ovirt-users] Migration of VM fails Failed in 'DestroyVDS' method Message: VDSM command failed: Virtual
> machine does not exist
>
>
> Dear collegues,
>
> please help us out. The migration of VMs from host to host fails, while we
> think that we configured everything properly. We searched through the
> mailing list and found nothing that describes/handles our error.
>
>
> The Details:
>
> We have three identical hosts and completed the self_hosted_engine
> installation on all of them (Host OS is the latest CentOS 7). As shared
> storage we use a NFS share hosted by an independent storage server. The
> shares are presented on a dedicated network: (192.168.23.0/24). All of the
> hosts have two networks. The management network is 192.168.10.0\24 and the
> 10Gbit storage network: 192.168.23.0/24.
>
> Our hosted engine (192.168.10.20) is up and running. All three hosts are
> connected and in status up. We create the second logical network "storage"
> for our physical storage network. Syncing and testing it on every host. This
> "storage" Network get the roles "migration" and "gluster" the Hosted-Engine
> UI.
> We create and mount our Data, Iso and Export domains in the Hosted-Engine UI
> over 192.168.23.0 (storage) network. We successfully install an CentOs 6 or
> 7 VM and can connect to them.
>
> Now if we try to migrate the VM, the migration fails.
>
>
> The Logs:
>
>
>
> ###################################################
> engine.log from the Engine VM
>
> ###################################################
>
>
> 2015-12-17 13:50:09,033 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand]
> (DefaultQuartzScheduler_Worker-34) [20ed2774] START,
> FullListVDSCommand(HostName = ,
> FullListVDSCommandParameters:{runAsync='true', hostId='62e30
> d77-fe4b-41d4-a9f7-b66d0a6ad7bd',
> vds='Host[,62e30d77-fe4b-41d4-a9f7-b66d0a6ad7bd]',
> vmIds='[408e7c39-d2a2-4412-8522-6eda216f17e0]'}), log id: 34cea1dd
> 2015-12-17 13:50:09,075 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand]
> (DefaultQuartzScheduler_Worker-34) [20ed2774] FINISH, FullListVDSCommand,
> return: [{status=Up, nicModel=rtl8139,pv, emulatedMachine=pc, guestDisk
> Mapping={398398f3-9572-4d67-8={name=/dev/vda}, QEMU_DVD-ROM={name=/dev/sr0}},
> vmId=408e7c39-d2a2-4412-8522-6eda216f17e0, pid=19010,
> devices=[Ljava.lang.Object;@69e4cf40, smp=4, vmType=kvm, displayIp=0,
> display=vnc, displaySecurePort=-1, m
> emSize=4096, displayPort=5900, cpuType=SandyBridge,
> spiceSecureChannels=smain,sdisplay,sinputs,scursor,splayback,srecord,ssmartcard,susbredir,
> statusTime=4455363570, vmName=HostedEngine, clientIp=, pauseCode=NOERR}],
> log id: 34cea1dd
> 2015-12-17 13:50:09,076 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand]
> (DefaultQuartzScheduler_Worker-34) [20ed2774] START,
> FullListVDSCommand(HostName = ,
> FullListVDSCommandParameters:{runAsync='true', hostId='62e30
> d77-fe4b-41d4-a9f7-b66d0a6ad7bd',
> vds='Host[,62e30d77-fe4b-41d4-a9f7-b66d0a6ad7bd]',
> vmIds='[0e956372-f4bd-4535-8472-73829277593f]'}), log id: 74f63ccf
> 2015-12-17 13:50:09,105 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand]
> (DefaultQuartzScheduler_Worker-34) [20ed2774] FINISH, FullListVDSCommand,
> return: [{acpiEnable=true, emulatedMachine=pc-i440fx-rhel7.2.0, tabletE
> nable=true, pid=30907, memGuaranteedSize=512, transparentHugePages=true,
> displaySecurePort=-1, spiceSslCipherSuite=DEFAULT, cpuType=SandyBridge,
> smp=1, pauseCode=NOERR, guestNumaNodes=[Ljava.lang.Object;@74afaff3,
> smartcardEnable=false, n
> umaTune={nodeset=0,1, mode=interleave}, custom={}, vmType=kvm, memSize=512,
> smpCoresPerSocket=1, vmName=tiny-i1, nice=0, status=Up, maxMemSize=4194304,
> bootMenuEnable=false, vmId=0e956372-f4bd-4535-8472-73829277593f,
> displayIp=0, displayP
> ort=5901, guestDiskMapping={},
> spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard,
> nicModel=rtl8139,pv, keyboardLayout=de, kvmEnable=true,
> pitReinjection=false, devices=[Ljava.lang.Object;@3a48b65e,
> display=vnc, timeOffset=3600, maxVCpus=16, clientIp=192.168.1.16,
> statusTime=4455363610, maxMemSlots=16}], log id: 74f63ccf
> 2015-12-17 13:50:09,106 INFO [org.ovirt.engine.core.vdsbroker.VmsMonitoring]
> (DefaultQuartzScheduler_Worker-34) [20ed2774] Received a memballoon Device
> without an address when processing VM 0e956372-f4bd-4535-8472-73829277593f
> devices, s
> kipping device: {device=memballoon, specParams={model=none},
> deviceType=balloon, type=balloon, alias=balloon0}
> 2015-12-17 13:50:09,106 INFO [org.ovirt.engine.core.vdsbroker.VmsMonitoring]
> (DefaultQuartzScheduler_Worker-34) [20ed2774] Received a vnc Device without
> an address when processing VM 0e956372-f4bd-4535-8472-73829277593f devices,
> skipping
> device: {device=vnc, deviceType=graphics, type=graphics,
> deviceId=c6ebce28-25d5-418c-a46d-0c21d61a62fd, port=5901}
> 2015-12-17 13:50:09,107 ERROR [org.ovirt.engine.core.vdsbroker.VmsMonitoring]
> (DefaultQuartzScheduler_Worker-34) [20ed2774] VM
> '0e956372-f4bd-4535-8472-73829277593f' managed non pluggable device was
> removed unexpectedly from libvirt: 'VmD
> evice:{id='VmDeviceId:{deviceId='62338ecf-adf4-4e12-826b-cc837e75055e',
> vmId='0e956372-f4bd-4535-8472-73829277593f'}', device='vnc',
> type='GRAPHICS', bootOrder='0', specParams='[]', address='', managed='true',
> plugged='false', readOnly='f
> alse', deviceAlias='', customProperties='[]', snapshotId='null',
> logicalName='null', usingScsiReservation='false'}'
> 2015-12-17 13:50:09,107 ERROR [org.ovirt.engine.core.vdsbroker.VmsMonitoring]
> (DefaultQuartzScheduler_Worker-34) [20ed2774] VM
> '0e956372-f4bd-4535-8472-73829277593f' managed non pluggable device was
> removed unexpectedly from libvirt: 'VmD
> evice:{id='VmDeviceId:{deviceId='8c2bad1b-ef19-4f43-9e62-d912f98e3901',
> vmId='0e956372-f4bd-4535-8472-73829277593f'}', device='cdrom', type='DISK',
> bootOrder='0', specParams='[path=]', address='', managed='true',
> plugged='false', readOnly
> ='true', deviceAlias='', customProperties='[]', snapshotId='null',
> logicalName='null', usingScsiReservation='false'}'
> 2015-12-17 13:50:24,185 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand]
> (DefaultQuartzScheduler_Worker-74) [50b5a02f] START,
> FullListVDSCommand(HostName = ,
> FullListVDSCommandParameters:{runAsync='true', hostId='62e30
> d77-fe4b-41d4-a9f7-b66d0a6ad7bd',
> vds='Host[,62e30d77-fe4b-41d4-a9f7-b66d0a6ad7bd]',
> vmIds='[408e7c39-d2a2-4412-8522-6eda216f17e0]'}), log id: 30a52aac
> 2015-12-17 13:50:25,103 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand]
> (DefaultQuartzScheduler_Worker-74) [50b5a02f] FINISH, FullListVDSCommand,
> return: [{status=Up, nicModel=rtl8139,pv, emulatedMachine=pc, guestDisk
> Mapping={398398f3-9572-4d67-8={name=/dev/vda}, QEMU_DVD-ROM={name=/dev/sr0}},
> vmId=408e7c39-d2a2-4412-8522-6eda216f17e0, pid=19010,
> devices=[Ljava.lang.Object;@793cf9d3, smp=4, vmType=kvm, displayIp=0,
> display=vnc, displaySecurePort=-1, m
> emSize=4096, displayPort=5900, cpuType=SandyBridge,
> spiceSecureChannels=smain,sdisplay,sinputs,scursor,splayback,srecord,ssmartcard,susbredir,
> statusTime=4455378730, vmName=HostedEngine, clientIp=, pauseCode=NOERR}],
> log id: 30a52aac
> 2015-12-17 13:50:40,230 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand]
> (DefaultQuartzScheduler_Worker-91) [6b1ec6a9] START,
> FullListVDSCommand(HostName = ,
> FullListVDSCommandParameters:{runAsync='true', hostId='62e30
> d77-fe4b-41d4-a9f7-b66d0a6ad7bd',
> vds='Host[,62e30d77-fe4b-41d4-a9f7-b66d0a6ad7bd]',
> vmIds='[408e7c39-d2a2-4412-8522-6eda216f17e0]'}), log id: 294d3ffe
> 2015-12-17 13:50:40,275 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand]
> (DefaultQuartzScheduler_Worker-91) [6b1ec6a9] FINISH, FullListVDSCommand,
> return: [{status=Up, nicModel=rtl8139,pv, emulatedMachine=pc, guestDisk
> Mapping={398398f3-9572-4d67-8={name=/dev/vda}, QEMU_DVD-ROM={name=/dev/sr0}},
> vmId=408e7c39-d2a2-4412-8522-6eda216f17e0, pid=19010,
> devices=[Ljava.lang.Object;@ea451e1, smp=4, vmType=kvm, displayIp=0,
> display=vnc, displaySecurePort=-1, me
> mSize=4096, displayPort=5900, cpuType=SandyBridge,
> spiceSecureChannels=smain,sdisplay,sinputs,scursor,splayback,srecord,ssmartcard,susbredir,
> statusTime=4455394760, vmName=HostedEngine, clientIp=, pauseCode=NOERR}],
> log id: 294d3ffe
> 2015-12-17 13:50:55,641 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand]
> (DefaultQuartzScheduler_Worker-5) [] START, FullListVDSCommand(HostName = ,
> FullListVDSCommandParameters:{runAsync='true', hostId='62e30d77-fe4b-
> 41d4-a9f7-b66d0a6ad7bd', vds='Host[,62e30d77-fe4b-41d4-a9f7-b66d0a6ad7bd]',
> vmIds='[408e7c39-d2a2-4412-8522-6eda216f17e0]'}), log id: 2aedaa54
> 2015-12-17 13:50:56,157 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand]
> (DefaultQuartzScheduler_Worker-5) [] FINISH, FullListVDSCommand, return:
> [{status=Up, nicModel=rtl8139,pv, emulatedMachine=pc, guestDiskMapping={
> 398398f3-9572-4d67-8={name=/dev/vda}, QEMU_DVD-ROM={name=/dev/sr0}},
> vmId=408e7c39-d2a2-4412-8522-6eda216f17e0, pid=19010,
> devices=[Ljava.lang.Object;@17b907dd, smp=4, vmType=kvm, displayIp=0,
> display=vnc, displaySecurePort=-1, memSize=40
> 96, displayPort=5900, cpuType=SandyBridge,
> spiceSecureChannels=smain,sdisplay,sinputs,scursor,splayback,srecord,ssmartcard,susbredir,
> statusTime=4455410180, vmName=HostedEngine, clientIp=, pauseCode=NOERR}],
> log id: 2aedaa54
> 2015-12-17 13:51:06,563 INFO
> [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (default task-4)
> [5e46a29f] Lock Acquired to object
> 'EngineLock:{exclusiveLocks='[0e956372-f4bd-4535-8472-73829277593f=<VM,
> ACTION_TYPE_FAILED_VM_IS_BEING_
> MIGRATED$VmName tiny-i1>]', sharedLocks='null'}'
> 2015-12-17 13:51:06,595 INFO
> [org.ovirt.engine.core.bll.scheduling.SchedulingManager] (default task-4)
> [5e46a29f] Candidate host 'hosted_engine_1'
> ('62e30d77-fe4b-41d4-a9f7-b66d0a6ad7bd') was filtered out by
> 'VAR__FILTERTYPE__INTERNAL' f
> ilter 'Migration' (correlation id: null)
> 2015-12-17 13:51:06,618 INFO
> [org.ovirt.engine.core.bll.MigrateVmToServerCommand]
> (org.ovirt.thread.pool-8-thread-20) [5e46a29f] Running command:
> MigrateVmToServerCommand internal: false. Entities affected : ID:
> 0e956372-f4bd-4535-8472-
> 73829277593f Type: VMAction group MIGRATE_VM with role type USER
> 2015-12-17 13:51:06,639 INFO
> [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand]
> (org.ovirt.thread.pool-8-thread-20) [5e46a29f] START, MigrateVDSCommand(
> MigrateVDSCommandParameters:{runAsync='true',
> hostId='62e30d77-fe4b-41d4-a9f7-b66d0
> a6ad7bd', vmId='0e956372-f4bd-4535-8472-73829277593f',
> srcHost='m1.example.de', dstVdsId='e3189b9a-b725-4a7c-987c-6b22bd4abea2',
> dstHost='n1.example.de:54321', migrationMethod='ONLINE',
> tunnelMigration='false', migrationDowntime='0', au
> toConverge='false', migrateCompressed='false', consoleAddress='null'}), log
> id: 25229fa3
> 2015-12-17 13:51:06,640 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand]
> (org.ovirt.thread.pool-8-thread-20) [5e46a29f] START,
> MigrateBrokerVDSCommand(HostName = hosted_engine_1,
> MigrateVDSCommandParameters:{runAs
> ync='true', hostId='62e30d77-fe4b-41d4-a9f7-b66d0a6ad7bd',
> vmId='0e956372-f4bd-4535-8472-73829277593f', srcHost='m1.example.de',
> dstVdsId='e3189b9a-b725-4a7c-987c-6b22bd4abea2',
> dstHost='n1.example.de:54321', migrationMethod='ONLINE', t
> unnelMigration='false', migrationDowntime='0', autoConverge='false',
> migrateCompressed='false', consoleAddress='null'}), log id: 4f18f441
> 2015-12-17 13:51:06,703 ERROR
> [org.ovirt.engine.core.bll.host.provider.foreman.SystemProviderFinder]
> (default task-6) [] Failed to find host on any provider by host name
> 'ov.example.de'
> 2015-12-17 13:51:07,184 ERROR
> [org.ovirt.engine.core.bll.host.provider.foreman.SystemProviderFinder]
> (default task-2) [] Failed to find host on any provider by host name
> 'ov.example.de'
> 2015-12-17 13:51:07,305 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand]
> (org.ovirt.thread.pool-8-thread-20) [5e46a29f] FINISH,
> MigrateBrokerVDSCommand, log id: 4f18f441
> 2015-12-17 13:51:07,310 INFO
> [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand]
> (org.ovirt.thread.pool-8-thread-20) [5e46a29f] FINISH, MigrateVDSCommand,
> return: MigratingFrom, log id: 25229fa3
> 2015-12-17 13:51:07,316 INFO
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (org.ovirt.thread.pool-8-thread-20) [5e46a29f] Correlation ID: 5e46a29f, Job
> ID: 8c267b6a-3d37-45b5-837c-39bcee545521, Call Stack: null,
> Custom Event ID: -1, Message: Migration started (VM: tiny-i1, Source:
> hosted_engine_1, Destination: hosted_engine_2, User: admin at internal).
> 2015-12-17 13:51:08,022 ERROR
> [org.ovirt.engine.core.bll.host.provider.foreman.SystemProviderFinder]
> (default task-15) [] Failed to find host on any provider by host name
> 'ov.example.de'
> 2015-12-17 13:51:11,224 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand]
> (DefaultQuartzScheduler_Worker-79) [] START, FullListVDSCommand(HostName = ,
> FullListVDSCommandParameters:{runAsync='true', hostId='62e30d77-fe4b
> -41d4-a9f7-b66d0a6ad7bd', vds='Host[,62e30d77-fe4b-41d4-a9f7-b66d0a6ad7bd]',
> vmIds='[408e7c39-d2a2-4412-8522-6eda216f17e0]'}), log id: c4b9f52
> 2015-12-17 13:51:11,254 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand]
> (DefaultQuartzScheduler_Worker-79) [] FINISH, FullListVDSCommand, return:
> [{status=Up, nicModel=rtl8139,pv, emulatedMachine=pc, guestDiskMapping=
> {398398f3-9572-4d67-8={name=/dev/vda}, QEMU_DVD-ROM={name=/dev/sr0}},
> vmId=408e7c39-d2a2-4412-8522-6eda216f17e0, pid=19010,
> devices=[Ljava.lang.Object;@54d8b81c, smp=4, vmType=kvm, displayIp=0,
> display=vnc, displaySecurePort=-1, memSize=4
> 096, displayPort=5900, cpuType=SandyBridge,
> spiceSecureChannels=smain,sdisplay,sinputs,scursor,splayback,srecord,ssmartcard,susbredir,
> statusTime=4455425760, vmName=HostedEngine, clientIp=, pauseCode=NOERR}],
> log id: c4b9f52
> 2015-12-17 13:51:12,232 INFO [org.ovirt.engine.core.vdsbroker.VmAnalyzer]
> (DefaultQuartzScheduler_Worker-83) [59659503] RefreshVmList VM id
> '0e956372-f4bd-4535-8472-73829277593f' is migrating to VDS 'hosted_engine_2'
> ignoring it in the r
> efresh until migration is done
> 2015-12-17 13:51:26,290 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand]
> (DefaultQuartzScheduler_Worker-21) [2fb3e350] START,
> FullListVDSCommand(HostName = ,
> FullListVDSCommandParameters:{runAsync='true', hostId='62e30
> d77-fe4b-41d4-a9f7-b66d0a6ad7bd',
> vds='Host[,62e30d77-fe4b-41d4-a9f7-b66d0a6ad7bd]',
> vmIds='[408e7c39-d2a2-4412-8522-6eda216f17e0]'}), log id: 29a38cc2
> 2015-12-17 13:51:26,690 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand]
> (DefaultQuartzScheduler_Worker-21) [2fb3e350] FINISH, FullListVDSCommand,
> return: [{status=Up, nicModel=rtl8139,pv, emulatedMachine=pc, guestDisk
> Mapping={398398f3-9572-4d67-8={name=/dev/vda}, QEMU_DVD-ROM={name=/dev/sr0}},
> vmId=408e7c39-d2a2-4412-8522-6eda216f17e0, pid=19010,
> devices=[Ljava.lang.Object;@306e29e9, smp=4, vmType=kvm, displayIp=0,
> display=vnc, displaySecurePort=-1, m
> emSize=4096, displayPort=5900, cpuType=SandyBridge,
> spiceSecureChannels=smain,sdisplay,sinputs,scursor,splayback,srecord,ssmartcard,susbredir,
> statusTime=4455440820, vmName=HostedEngine, clientIp=, pauseCode=NOERR}],
> log id: 29a38cc2
> 2015-12-17 13:51:27,295 INFO [org.ovirt.engine.core.vdsbroker.VmAnalyzer]
> (DefaultQuartzScheduler_Worker-85) [] RefreshVmList VM id
> '0e956372-f4bd-4535-8472-73829277593f' is migrating to VDS 'hosted_engine_2'
> ignoring it in the refresh u
> ntil migration is done
> 2015-12-17 13:51:41,726 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand]
> (DefaultQuartzScheduler_Worker-60) [] START, FullListVDSCommand(HostName = ,
> FullListVDSCommandParameters:{runAsync='true', hostId='62e30d77-fe4b
> -41d4-a9f7-b66d0a6ad7bd', vds='Host[,62e30d77-fe4b-41d4-a9f7-b66d0a6ad7bd]',
> vmIds='[408e7c39-d2a2-4412-8522-6eda216f17e0]'}), log id: 224c57c9
> 2015-12-17 13:51:42,263 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand]
> (DefaultQuartzScheduler_Worker-60) [] FINISH, FullListVDSCommand, return:
> [{status=Up, nicModel=rtl8139,pv, emulatedMachine=pc, guestDiskMapping=
> {398398f3-9572-4d67-8={name=/dev/vda}, QEMU_DVD-ROM={name=/dev/sr0}},
> vmId=408e7c39-d2a2-4412-8522-6eda216f17e0, pid=19010,
> devices=[Ljava.lang.Object;@29eb6e5, smp=4, vmType=kvm, displayIp=0,
> display=vnc, displaySecurePort=-1, memSize=40
> 96, displayPort=5900, cpuType=SandyBridge,
> spiceSecureChannels=smain,sdisplay,sinputs,scursor,splayback,srecord,ssmartcard,susbredir,
> statusTime=4455456260, vmName=HostedEngine, clientIp=, pauseCode=NOERR}],
> log id: 224c57c9
> 2015-12-17 13:51:42,311 INFO [org.ovirt.engine.core.vdsbroker.VmAnalyzer]
> (DefaultQuartzScheduler_Worker-71) [433f9bb6] RefreshVmList VM id
> '0e956372-f4bd-4535-8472-73829277593f' is migrating to VDS 'hosted_engine_2'
> ignoring it in the r
> efresh until migration is done
> 2015-12-17 13:51:47,215 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand]
> (ForkJoinPool-1-worker-294) [] START, DestroyVDSCommand(HostName =
> hosted_engine_2, DestroyVmVDSCommandParameters:{runAsync='true',
> hostId='e3189b
> 9a-b725-4a7c-987c-6b22bd4abea2', vmId='0e956372-f4bd-4535-8472-73829277593f',
> force='false', secondsToWait='0', gracefully='false', reason=''}), log id:
> 24778267
> 2015-12-17 13:51:47,318 ERROR
> [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand]
> (ForkJoinPool-1-worker-294) [] Failed in 'DestroyVDS' method
> 2015-12-17 13:51:47,321 ERROR
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (ForkJoinPool-1-worker-294) [] Correlation ID: null, Call Stack: null,
> Custom Event ID: -1, Message: VDSM hosted_engine_2 command failed:
> Virtual machine does not exist
> 2015-12-17 13:51:47,321 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand]
> (ForkJoinPool-1-worker-294) [] Command
> 'org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand' return value
> 'StatusOnlyReturnForXmlRpc [stat
> us=StatusForXmlRpc [code=1, message=Virtual machine does not exist]]'
> 2015-12-17 13:51:47,321 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand]
> (ForkJoinPool-1-worker-294) [] HostName = hosted_engine_2
> 2015-12-17 13:51:47,321 ERROR
> [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand]
> (ForkJoinPool-1-worker-294) [] Command 'DestroyVDSCommand(HostName =
> hosted_engine_2, DestroyVmVDSCommandParameters:{runAsync='true',
> hostId='e318
> 9b9a-b725-4a7c-987c-6b22bd4abea2',
> vmId='0e956372-f4bd-4535-8472-73829277593f', force='false',
> secondsToWait='0', gracefully='false', reason=''})' execution failed:
> VDSGenericException: VDSErrorException: Failed to DestroyVDS, error = Vir
> tual machine does not exist, code = 1
> 2015-12-17 13:51:47,321 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand]
> (ForkJoinPool-1-worker-294) [] FINISH, DestroyVDSCommand, log id: 24778267
> 2015-12-17 13:51:47,322 INFO [org.ovirt.engine.core.vdsbroker.VmAnalyzer]
> (ForkJoinPool-1-worker-294) [] RefreshVmList VM id
> '0e956372-f4bd-4535-8472-73829277593f' status = 'Down' on VDS
> 'hosted_engine_2' ignoring it in the refresh until
> migration is done
> 2015-12-17 13:51:49,203 ERROR
> [org.ovirt.engine.core.bll.host.provider.foreman.SystemProviderFinder]
> (default task-42) [] Failed to find host on any provider by host name
> 'ov.example.de'
> 2015-12-17 13:51:55,416 INFO
> [org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient] (SSL Stomp Reactor)
> [] Connecting to n1.example.de/192.168.10.12
> 2015-12-17 13:51:57,272 INFO
> [org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient] (SSL Stomp Reactor)
> [] Connecting to m1.example.de/192.168.10.11
> 2015-12-17 13:51:57,916 INFO [org.ovirt.engine.core.vdsbroker.VmAnalyzer]
> (DefaultQuartzScheduler_Worker-28) [ff193b8] VM
> '0e956372-f4bd-4535-8472-73829277593f'(tiny-i1) moved from 'MigratingFrom'
> --> 'Up'
> 2015-12-17 13:51:57,916 INFO [org.ovirt.engine.core.vdsbroker.VmAnalyzer]
> (DefaultQuartzScheduler_Worker-28) [ff193b8] Adding VM
> '0e956372-f4bd-4535-8472-73829277593f' to re-run list
>
>
>
>
> ###################################################
> The vdsm.log on Source Host:
>
> ###################################################
>
>
> Thread-103967::DEBUG::2015-12-17
> 14:51:40,619::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd
> if=/rhev/data-center/mnt/192.168.23.10:_mnt_sdb_nfs_ISO/e793de29-f95f-4512-9a57-ece72268b53f/dom_md/metadata
> iflag=direct of=/dev/
> null bs=4096 count=1 (cwd None)
> Thread-103967::DEBUG::2015-12-17
> 14:51:40,626::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
> <err> = '0+1 records in\n0+1 records out\n330 bytes (330 B) copied,
> 0.00023453 s, 1.4 MB/s\n'; <rc> = 0
> Reactor thread::INFO::2015-12-17
> 14:51:41,423::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept)
> Accepting connection from 127.0.0.1:36777
> Reactor thread::DEBUG::2015-12-17
> 14:51:41,427::protocoldetector::82::ProtocolDetector.Detector::(__init__)
> Using required_size=11
> Reactor thread::INFO::2015-12-17
> 14:51:41,428::protocoldetector::118::ProtocolDetector.Detector::(handle_read)
> Detected protocol xml from 127.0.0.1:36777
> Reactor thread::DEBUG::2015-12-17
> 14:51:41,428::bindingxmlrpc::1297::XmlDetector::(handle_socket) xml over
> http detected from ('127.0.0.1', 36777)
> BindingXMLRPC::INFO::2015-12-17
> 14:51:41,428::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting
> request handler for 127.0.0.1:36777
> Thread-108220::INFO::2015-12-17
> 14:51:41,429::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request
> handler for 127.0.0.1:36777 started
> Thread-108220::DEBUG::2015-12-17
> 14:51:41,431::task::595::Storage.TaskManager.Task::(_updateState)
> Task=`2cdd058a-ef2c-4eea-a172-33b07f23be33`::moving from state init -> state
> preparing
> Thread-108220::INFO::2015-12-17
> 14:51:41,432::logUtils::48::dispatcher::(wrapper) Run and protect:
> repoStats(options=None)
> Thread-108220::INFO::2015-12-17
> 14:51:41,432::logUtils::51::dispatcher::(wrapper) Run and protect:
> repoStats, Return response: {u'94048698-25fe-4f3e-8f49-34b8633ee996':
> {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay':
> '0.000238152', 'lastCheck': '6.9', 'valid': True},
> u'e793de29-f95f-4512-9a57-ece72268b53f': {'code': 0, 'actual': True,
> 'version': 0, 'acquired': True, 'delay': '0.00023453', 'lastCheck': '0.8',
> 'valid': True}, 'fac2b63e-4359-4ad8-871c-58
> ae92254ba9': {'code': 0, 'actual': True, 'version': 3, 'acquired': True,
> 'delay': '0.000251451', 'lastCheck': '8.3', 'valid': True},
> u'ff24327d-3080-4344-b083-43cc5acd5342': {'code': 0, 'actual': True,
> 'version': 3, 'acquired': True, 'del
> ay': '0.000231135', 'lastCheck': '8.5', 'valid': True}}
> Thread-108220::DEBUG::2015-12-17
> 14:51:41,432::task::1191::Storage.TaskManager.Task::(prepare)
> Task=`2cdd058a-ef2c-4eea-a172-33b07f23be33`::finished:
> {u'94048698-25fe-4f3e-8f49-34b8633ee996': {'code': 0, 'actual': True,
> 'version': 0, 'acq
> uired': True, 'delay': '0.000238152', 'lastCheck': '6.9', 'valid': True},
> u'e793de29-f95f-4512-9a57-ece72268b53f': {'code': 0, 'actual': True,
> 'version': 0, 'acquired': True, 'delay': '0.00023453', 'lastCheck': '0.8',
> 'valid': True}, 'fac
> 2b63e-4359-4ad8-871c-58ae92254ba9': {'code': 0, 'actual': True, 'version': 3,
> 'acquired': True, 'delay': '0.000251451', 'lastCheck': '8.3', 'valid':
> True}, u'ff24327d-3080-4344-b083-43cc5acd5342': {'code': 0, 'actual': True,
> 'version': 3,
> 'acquired': True, 'delay': '0.000231135', 'lastCheck': '8.5', 'valid':
> True}}
> Thread-108220::DEBUG::2015-12-17
> 14:51:41,432::task::595::Storage.TaskManager.Task::(_updateState)
> Task=`2cdd058a-ef2c-4eea-a172-33b07f23be33`::moving from state preparing ->
> state finished
> Thread-108220::DEBUG::2015-12-17
> 14:51:41,432::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll)
> Owner.releaseAll requests {} resources {}
> Thread-108220::DEBUG::2015-12-17
> 14:51:41,432::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll)
> Owner.cancelAll requests {}
> Thread-108220::DEBUG::2015-12-17
> 14:51:41,432::task::993::Storage.TaskManager.Task::(_decref)
> Task=`2cdd058a-ef2c-4eea-a172-33b07f23be33`::ref 0 aborting False
> Thread-108220::INFO::2015-12-17
> 14:51:41,489::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request
> handler for 127.0.0.1:36777 stopped
> Thread-108162::WARNING::2015-12-17
> 14:51:41,931::migration::526::virt.vm::(monitor_migration)
> vmId=`0e956372-f4bd-4535-8472-73829277593f`::The migration took 40 seconds
> which is exceeding the configured maximum time for migrations of 32 s
> econds. The migration will be aborted.
> Thread-108162::DEBUG::2015-12-17
> 14:51:41,933::migration::558::virt.vm::(stop)
> vmId=`0e956372-f4bd-4535-8472-73829277593f`::stopping migration monitor
> thread
> Thread-108160::DEBUG::2015-12-17
> 14:51:42,372::migration::558::virt.vm::(stop)
> vmId=`0e956372-f4bd-4535-8472-73829277593f`::stopping migration monitor
> thread
> Thread-108160::DEBUG::2015-12-17
> 14:51:42,372::migration::453::virt.vm::(stop)
> vmId=`0e956372-f4bd-4535-8472-73829277593f`::stopping migration downtime
> thread
> Thread-108161::DEBUG::2015-12-17 14:51:42,372::migration::450::virt.vm::(run)
> vmId=`0e956372-f4bd-4535-8472-73829277593f`::migration downtime thread
> exiting
> Thread-108160::ERROR::2015-12-17
> 14:51:42,372::migration::208::virt.vm::(_recover)
> vmId=`0e956372-f4bd-4535-8472-73829277593f`::Operation abgebrochen:
> Migrations-Job: abgebrochen durch Client
> Thread-108160::DEBUG::2015-12-17
> 14:51:42,373::stompreactor::389::jsonrpc.AsyncoreClient::(send) Sending
> response
> Thread-108160::DEBUG::2015-12-17
> 14:51:42,406::__init__::206::jsonrpc.Notification::(emit) Sending event
> {"params": {"notify_time": 4455461740,
> "0e956372-f4bd-4535-8472-73829277593f": {"status": "Migration Source"}},
> "jsonrpc": "2.0", "me
> thod": "|virt|VM_status|0e956372-f4bd-4535-8472-73829277593f"}
> Thread-108160::ERROR::2015-12-17 14:51:42,407::migration::310::virt.vm::(run)
> vmId=`0e956372-f4bd-4535-8472-73829277593f`::Failed to migrate
> Traceback (most recent call last):
> File "/usr/share/vdsm/virt/migration.py", line 294, in run
> self._startUnderlyingMigration(time.time())
> File "/usr/share/vdsm/virt/migration.py", line 364, in
> _startUnderlyingMigration
> self._perform_migration(duri, muri)
> File "/usr/share/vdsm/virt/migration.py", line 403, in _perform_migration
> self._vm._dom.migrateToURI3(duri, params, flags)
> File "/usr/share/vdsm/virt/virdomain.py", line 68, in f
> ret = attr(*args, **kwargs)
> File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py", line
> 124, in wrapper
> ret = f(*args, **kwargs)
> File "/usr/lib64/python2.7/site-packages/libvirt.py", line 1836, in
> migrateToURI3
> if ret == -1: raise libvirtError ('virDomainMigrateToURI3() failed',
> dom=self)
> libvirtError: Operation abgebrochen: Migrations-Job: abgebrochen durch Client
> Thread-103715::DEBUG::2015-12-17
> 14:51:42,895::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd
> if=/rhev/data-center/mnt/192.168.23.10:_mnt_sdb_nfs_DATA/ff24327d-3080-4344-b083-43cc5acd5342/dom_md/metadata
> iflag=direct of=/dev
> /null bs=4096 count=1 (cwd None)
> Thread-103715::DEBUG::2015-12-17
> 14:51:42,905::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
> <err> = '0+1 records in\n0+1 records out\n463 bytes (463 B) copied,
> 0.000402171 s, 1.2 MB/s\n'; <rc> = 0
> Thread-113::DEBUG::2015-12-17
> 14:51:43,093::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd
> if=/rhev/data-center/mnt/192.168.23.10:_mnt_sdb_nfs_HOSTED__ENGINE/fac2b63e-4359-4ad8-871c-58ae92254ba9/dom_md/metadata
> iflag=direct
> of=/dev/null bs=4096 count=1 (cwd None)
> Thread-113::DEBUG::2015-12-17
> 14:51:43,100::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
> <err> = '0+1 records in\n0+1 records out\n316 bytes (316 B) copied,
> 0.000300531 s, 1.1 MB/s\n'; <rc> = 0
>
>
>
>
> ##################################
> vdsm.log on target
> ##################################
>
> (Is too long and attached) but below are the significant lines:
>
>
> 1:32,193::periodic::254::virt.periodic.VmDispatcher::(__call__) could not run
> <class 'virt.periodic.DriveWatermarkMonitor'> on
> [u'0e956372-f4bd-4535-8472-73829277593f']
> Thread-4556::DEBUG::2015-12-17
> 14:51:32,752::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd
> if=/rhev/data-center/mnt/192.168.23.10:_mnt_sdb_nfs_ISO/e793de29-f95f-4512-9a57-ece72268b53f/dom_md/metadata
> iflag=direct of=/dev/nu
> ll bs=4096 count=1 (cwd None)
> Thread-4556::DEBUG::2015-12-17
> 14:51:32,760::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
> <err> = '0+1 records in\n0+1 records out\n330 bytes (330 B) copied,
> 0.000202573 s, 1.6 MB/s\n'; <rc> = 0
> Thread-4246::DEBUG::2015-12-17
> 14:51:33,185::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd
> if=/rhev/data-center/mnt/192.168.23.10:_mnt_sdb_nfs_DATA/ff24327d-3080-4344-b083-43cc5acd5342/dom_md/metadata
> iflag=direct of=/dev/n
> ull bs=4096 count=1 (cwd None)
> Thread-4246::DEBUG::2015-12-17
> 14:51:33,194::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
> <err> = '0+1 records in\n0+1 records out\n463 bytes (463 B) copied,
> 0.000259942 s, 1.8 MB/s\n'; <rc> = 0
> periodic/4::WARNING::2015-12-17
> 14:51:34,193::periodic::254::virt.periodic.VmDispatcher::(__call__) could
> not run <class 'virt.periodic.DriveWatermarkMonitor'> on
> [u'0e956372-f4bd-4535-8472-73829277593f']
> periodic/2::WARNING::2015-12-17
> 14:51:36,194::periodic::254::virt.periodic.VmDispatcher::(__call__) could
> not run <class 'virt.periodic.DriveWatermarkMonitor'> on
> [u'0e956372-f4bd-4535-8472-73829277593f']
> periodic/1::WARNING::2015-12-17
> 14:51:36,615::periodic::254::virt.periodic.VmDispatcher::(__call__) could
> not run <class 'virt.periodic.BlockjobMonitor'> on
> [u'0e956372-f4bd-4535-8472-73829277593f']
> periodic/4::WARNING::2015-12-17
> 14:51:36,615::periodic::277::virt.vm::(__call__)
> vmId=`0e956372-f4bd-4535-8472-73829277593f`::could not run on
> 0e956372-f4bd-4535-8472-73829277593f: domain not connected
> periodic/2::DEBUG::2015-12-17
> 14:51:36,625::sampling::531::virt.sampling.VMBulkSampler::(__call__)
> sampling 0 domains
> .....
>
> Thread-8857::INFO::2015-12-17
> 14:51:40,738::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request
> handler for 127.0.0.1:58492 stopped
> periodic/4::WARNING::2015-12-17
> 14:51:42,197::periodic::254::virt.periodic.VmDispatcher::(__call__) could
> not run <class 'virt.periodic.DriveWatermarkMonitor'> on
> [u'0e956372-f4bd-4535-8472-73829277593f']
> Thread-4556::DEBUG::2015-12-17
> 14:51:42,763::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd
> if=/rhev/data-center/mnt/192.168.23.10:_mnt_sdb_nfs_ISO/e793de29-f95f-4512-9a57-ece72268b53f/dom_md/metadata
> iflag=direct of=/dev/nu
> ll bs=4096 count=1 (cwd None)
> Thread-4556::DEBUG::2015-12-17
> 14:51:42,770::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
> <err> = '0+1 records in\n0+1 records out\n330 bytes (330 B) copied,
> 0.000225483 s, 1.5 MB/s\n'; <rc> = 0
> Thread-4246::DEBUG::2015-12-17
> 14:51:43,199::fileSD::173::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd
> if=/rhev/data-center/mnt/192.168.23.10:_mnt_sdb_nfs_DATA/ff24327d-3080-4344-b083-43cc5acd5342/dom_md/metadata
> iflag=direct of=/dev/n
> ull bs=4096 count=1 (cwd None)
> Thread-4246::DEBUG::2015-12-17
> 14:51:43,207::fileSD::173::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
> <err> = '0+1 records in\n0+1 records out\n463 bytes (463 B) copied,
> 0.000226464 s, 2.0 MB/s\n'; <rc> = 0
> periodic/2::WARNING::2015-12-17
> 14:51:44,198::periodic::254::virt.periodic.VmDispatcher::(__call__) could
> not run <class 'virt.periodic.DriveWatermarkMonitor'> on
> [u'0e956372-f4bd-4535-8472-73829277593f']
>
> .....
>
> Thread-8781::ERROR::2015-12-17
> 14:51:46,636::vm::752::virt.vm::(_startUnderlyingVm)
> vmId=`0e956372-f4bd-4535-8472-73829277593f`::Failed to start a migration
> destination vm
> Traceback (most recent call last):
> File "/usr/share/vdsm/virt/vm.py", line 721, in _startUnderlyingVm
> self._completeIncomingMigration()
> File "/usr/share/vdsm/virt/vm.py", line 2785, in _completeIncomingMigration
> self._incomingMigrationFinished.isSet(), usedTimeout)
> File "/usr/share/vdsm/virt/vm.py", line 2838, in
> _attachLibvirtDomainAfterMigration
> raise MigrationError(e.get_error_message())
> MigrationError: Domain nicht gefunden: Keine Domain mit ��bereinstimmender
> UUID '0e956372-f4bd-4535-8472-73829277593f'
> _______________________________________________
> Users mailing list
> Users at ovirt.org
> http://lists.ovirt.org/mailman/listinfo/users
>
More information about the Users
mailing list