VM with multiple vdisks can't migrate
------=_=-_OpenGroupware_org_NGMime-15477-1518516470.384163-4------ Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable Content-Length: 29601 Hi all, I discovered yesterday a problem when migrating VM with more than one v= disk. On our test servers (oVirt4.1, shared storage with Gluster), I created = 2 VMs needed for a test, from a template with a 20G vdisk. On this VMs = I added a 100G vdisk (for this tests I didn't want to waste time to ext= end the existing vdisks... But I lost time finally...). The VMs with th= e 2 vdisks works well. Now I saw some updates waiting on the host. I tried to put it in mainte= nance... But it stopped on the two VM. They were marked "migrating", bu= t no more accessible. Other (small) VMs with only 1 vdisk was migrated = without problem at the same time. I saw that a kvm process for the (big) VMs was launched on the source A= ND destination host, but after tens of minutes, the migration and the V= Ms was always freezed. I tried to cancel the migration for the VMs : fa= iled. The only way to stop it was to poweroff the VMs : the kvm process= died on the 2 hosts and the GUI alerted on a failed migration. In doubt, I tried to delete the second vdisk on one of this VMs : it mi= grates then without error ! And no access problem. I tried to extend the first vdisk of the second VM, the delete the seco= nd vdisk : it migrates now without problem !=C2=A0=C2=A0=C2=A0 So after another test with a VM with 2 vdisks, I can say that this bloc= ked the migration process :( In engine.log, for a VMs with 1 vdisk migrating well, we see :2018-02-1= 2 16:46:29,705+01 INFO =C2=A0[org.ovirt.engine.core.bll.MigrateVmToServ= erCommand] (default task-28) [2f712024-5982-46a8-82c8-fd8293da5725] Loc= k Acquired to object 'EngineLock:{exclusiveLocks=3D'[3f57e669-5e4c-4d10= -85cc-d573004a099d=3DVM]', sharedLocks=3D''}' 2018-02-12 16:46:29,955+01 INFO =C2=A0[org.ovirt.engine.core.bll.Migrat= eVmToServerCommand] (org.ovirt.thread.pool-6-thread-32) [2f712024-5982-= 46a8-82c8-fd8293da5725] Running command: MigrateVmToServerCommand inter= nal: false. Entities affected : =C2=A0ID: 3f57e669-5e4c-4d10-85cc-d5730= 04a099d Type: VMAction group MIGRATE=5FVM with role type USER 2018-02-12 16:46:30,261+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= MigrateVDSCommand] (org.ovirt.thread.pool-6-thread-32) [2f712024-5982-4= 6a8-82c8-fd8293da5725] START, MigrateVDSCommand( MigrateVDSCommandParam= eters:{runAsync=3D'true', hostId=3D'ce3938b1-b23f-4d22-840a-f17d7cd87bb= 1', vmId=3D'3f57e669-5e4c-4d10-85cc-d573004a099d', srcHost=3D'192.168.0= .6', dstVdsId=3D'd569c2dd-8f30-4878-8aea-858db285cf69', dstHost=3D'192.= 168.0.5:54321', migrationMethod=3D'ONLINE', tunnelMigration=3D'false', = migrationDowntime=3D'0', autoConverge=3D'true', migrateCompressed=3D'fa= lse', consoleAddress=3D'null', maxBandwidth=3D'500', enableGuestEvents=3D= 'true', maxIncomingMigrations=3D'2', maxOutgoingMigrations=3D'2', conve= rgenceSchedule=3D'[init=3D[{name=3DsetDowntime, params=3D[100]}], stall= ing=3D[{limit=3D1, action=3D{name=3DsetDowntime, params=3D[150]}}, {lim= it=3D2, action=3D{name=3DsetDowntime, params=3D[200]}}, {limit=3D3, act= ion=3D{name=3DsetDowntime, params=3D[300]}}, {limit=3D4, action=3D{name= =3DsetDowntime, params=3D[400]}}, {limit=3D6, action=3D{name=3DsetDownt= ime, params=3D[500]}}, {limit=3D-1, action=3D{name=3Dabort, params=3D[]= }}]]'}), log id: 14f61ee0 2018-02-12 16:46:30,262+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= vdsbroker.MigrateBrokerVDSCommand] (org.ovirt.thread.pool-6-thread-32) = [2f712024-5982-46a8-82c8-fd8293da5725] START, MigrateBrokerVDSCommand(H= ostName =3D victor.local.systea.fr, MigrateVDSCommandParameters:{runAsy= nc=3D'true', hostId=3D'ce3938b1-b23f-4d22-840a-f17d7cd87bb1', vmId=3D'3= f57e669-5e4c-4d10-85cc-d573004a099d', srcHost=3D'192.168.0.6', dstVdsId= =3D'd569c2dd-8f30-4878-8aea-858db285cf69', dstHost=3D'192.168.0.5:54321= ', migrationMethod=3D'ONLINE', tunnelMigration=3D'false', migrationDown= time=3D'0', autoConverge=3D'true', migrateCompressed=3D'false', console= Address=3D'null', maxBandwidth=3D'500', enableGuestEvents=3D'true', max= IncomingMigrations=3D'2', maxOutgoingMigrations=3D'2', convergenceSched= ule=3D'[init=3D[{name=3DsetDowntime, params=3D[100]}], stalling=3D[{lim= it=3D1, action=3D{name=3DsetDowntime, params=3D[150]}}, {limit=3D2, act= ion=3D{name=3DsetDowntime, params=3D[200]}}, {limit=3D3, action=3D{name= =3DsetDowntime, params=3D[300]}}, {limit=3D4, action=3D{name=3DsetDownt= ime, params=3D[400]}}, {limit=3D6, action=3D{name=3DsetDowntime, params= =3D[500]}}, {limit=3D-1, action=3D{name=3Dabort, params=3D[]}}]]'}), lo= g id: 775cd381 2018-02-12 16:46:30,277+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= vdsbroker.MigrateBrokerVDSCommand] (org.ovirt.thread.pool-6-thread-32) = [2f712024-5982-46a8-82c8-fd8293da5725] FINISH, MigrateBrokerVDSCommand,= log id: 775cd381 2018-02-12 16:46:30,285+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= MigrateVDSCommand] (org.ovirt.thread.pool-6-thread-32) [2f712024-5982-4= 6a8-82c8-fd8293da5725] FINISH, MigrateVDSCommand, return: MigratingFrom= , log id: 14f61ee0 2018-02-12 16:46:30,301+01 INFO =C2=A0[org.ovirt.engine.core.dal.dbbrok= er.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-3= 2) [2f712024-5982-46a8-82c8-fd8293da5725] EVENT=5FID: VM=5FMIGRATION=5F= START(62), Correlation ID: 2f712024-5982-46a8-82c8-fd8293da5725, Job ID= : 4bd19aa9-cc99-4d02-884e-5a1e857a7738, Call Stack: null, Custom ID: nu= ll, Custom Event ID: -1, Message: Migration started (VM: Oracle=5FSECON= DARY, Source: victor.local.systea.fr, Destination: ginger.local.systea.= fr, User: admin@internal-authz). 2018-02-12 16:46:31,106+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= vdsbroker.FullListVDSCommand] (DefaultQuartzScheduler9) [54a65b66] STAR= T, FullListVDSCommand(HostName =3D victor.local.systea.fr, FullListVDSC= ommandParameters:{runAsync=3D'true', hostId=3D'ce3938b1-b23f-4d22-840a-= f17d7cd87bb1', vmIds=3D'[3f57e669-5e4c-4d10-85cc-d573004a099d]'}), log = id: 54b4b435 2018-02-12 16:46:31,147+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= vdsbroker.FullListVDSCommand] (DefaultQuartzScheduler9) [54a65b66] FINI= SH, FullListVDSCommand, return: [{acpiEnable=3Dtrue, emulatedMachine=3D= pc-i440fx-rhel7.3.0, tabletEnable=3Dtrue, pid=3D1493, guestDiskMapping=3D= {0QEMU=5FQEMU=5FHARDDISK=5Fd890fa68-fba4-4f49-9=3D{name=3D/dev/sda}, QE= MU=5FDVD-ROM=5FQM00003=3D{name=3D/dev/sr0}}, transparentHugePages=3Dtru= e, timeOffset=3D0, cpuType=3DNehalem, smp=3D2, pauseCode=3DNOERR, guest= NumaNodes=3D[Ljava.lang.Object;@1d9042cd, smartcardEnable=3Dfalse, cust= om=3D{device=5Ffbddd528-7d93-49c6-a286-180e021cb274device=5F879c93ab-4d= f1-435c-af02-565039fcc254=3DVmDevice:{id=3D'VmDeviceId:{deviceId=3D'879= c93ab-4df1-435c-af02-565039fcc254', vmId=3D'3f57e669-5e4c-4d10-85cc-d57= 3004a099d'}', device=3D'unix', type=3D'CHANNEL', bootOrder=3D'0', specP= arams=3D'[]', address=3D'{bus=3D0, controller=3D0, type=3Dvirtio-serial= , port=3D1}', managed=3D'false', plugged=3D'true', readOnly=3D'false', = deviceAlias=3D'channel0', customProperties=3D'[]', snapshotId=3D'null',= logicalName=3D'null', hostDevice=3D'null'}, device=5Ffbddd528-7d93-49c= 6-a286-180e021cb274device=5F879c93ab-4df1-435c-af02-565039fcc254device=5F= 8945f61a-abbe-4156-8485-a4aa6f1908dbdevice=5F017b5e59-01c4-4aac-bf0c-b5= d9557284d6=3DVmDevice:{id=3D'VmDeviceId:{deviceId=3D'017b5e59-01c4-4aac= -bf0c-b5d9557284d6', vmId=3D'3f57e669-5e4c-4d10-85cc-d573004a099d'}', d= evice=3D'tablet', type=3D'UNKNOWN', bootOrder=3D'0', specParams=3D'[]',= address=3D'{bus=3D0, type=3Dusb, port=3D1}', managed=3D'false', plugge= d=3D'true', readOnly=3D'false', deviceAlias=3D'input0', customPropertie= s=3D'[]', snapshotId=3D'null', logicalName=3D'null', hostDevice=3D'null= '}, device=5Ffbddd528-7d93-49c6-a286-180e021cb274=3DVmDevice:{id=3D'VmD= eviceId:{deviceId=3D'fbddd528-7d93-49c6-a286-180e021cb274', vmId=3D'3f5= 7e669-5e4c-4d10-85cc-d573004a099d'}', device=3D'ide', type=3D'CONTROLLE= R', bootOrder=3D'0', specParams=3D'[]', address=3D'{slot=3D0x01, bus=3D= 0x00, domain=3D0x0000, type=3Dpci, function=3D0x1}', managed=3D'false',= plugged=3D'true', readOnly=3D'false', deviceAlias=3D'ide', customPrope= rties=3D'[]', snapshotId=3D'null', logicalName=3D'null', hostDevice=3D'= null'}, device=5Ffbddd528-7d93-49c6-a286-180e021cb274device=5F879c93ab-= 4df1-435c-af02-565039fcc254device=5F8945f61a-abbe-4156-8485-a4aa6f1908d= b=3DVmDevice:{id=3D'VmDeviceId:{deviceId=3D'8945f61a-abbe-4156-8485-a4a= a6f1908db', vmId=3D'3f57e669-5e4c-4d10-85cc-d573004a099d'}', device=3D'= unix', type=3D'CHANNEL', bootOrder=3D'0', specParams=3D'[]', address=3D= '{bus=3D0, controller=3D0, type=3Dvirtio-serial, port=3D2}', managed=3D= 'false', plugged=3D'true', readOnly=3D'false', deviceAlias=3D'channel1'= , customProperties=3D'[]', snapshotId=3D'null', logicalName=3D'null', h= ostDevice=3D'null'}}, vmType=3Dkvm, memSize=3D8192, smpCoresPerSocket=3D= 1, vmName=3DOracle=5FSECONDARY, nice=3D0, status=3DMigration Source, ma= xMemSize=3D32768, bootMenuEnable=3Dfalse, vmId=3D3f57e669-5e4c-4d10-85c= c-d573004a099d, numOfIoThreads=3D2, smpThreadsPerCore=3D1, memGuarantee= dSize=3D8192, kvmEnable=3Dtrue, pitReinjection=3Dfalse, displayNetwork=3D= ovirtmgmt, devices=3D[Ljava.lang.Object;@28ae66d7, display=3Dvnc, maxVC= pus=3D16, clientIp=3D, statusTime=3D4299484520, maxMemSlots=3D16}], log= id: 54b4b435 2018-02-12 16:46:31,150+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= monitoring.VmsStatisticsFetcher] (DefaultQuartzScheduler1) [27fac647] F= etched 3 VMs from VDS 'd569c2dd-8f30-4878-8aea-858db285cf69' 2018-02-12 16:46:31,151+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= monitoring.VmDevicesMonitoring] (DefaultQuartzScheduler9) [54a65b66] Re= ceived a vnc Device without an address when processing VM 3f57e669-5e4c= -4d10-85cc-d573004a099d devices, skipping device: {device=3Dvnc, specPa= rams=3D{displayNetwork=3Dovirtmgmt, keyMap=3Dfr, displayIp=3D192.168.0.= 6}, type=3Dgraphics, deviceId=3D813957b1-446a-4e88-9e40-9fe76d2c442d, p= ort=3D5901} 2018-02-12 16:46:31,151+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= monitoring.VmDevicesMonitoring] (DefaultQuartzScheduler9) [54a65b66] Re= ceived a lease Device without an address when processing VM 3f57e669-5e= 4c-4d10-85cc-d573004a099d devices, skipping device: {lease=5Fid=3D3f57e= 669-5e4c-4d10-85cc-d573004a099d, sd=5Fid=3D1e51cecc-eb2e-47d0-b185-920f= dc7afa16, deviceId=3D{uuid=3Da09949aa-5642-4b6d-94a4-8b0d04257be5}, off= set=3D6291456, device=3Dlease, path=3D/rhev/data-center/mnt/glusterSD/1= 92.168.0.6:=5FDATA01/1e51cecc-eb2e-47d0-b185-920fdc7afa16/dom=5Fmd/xlea= ses, type=3Dlease} 2018-02-12 16:46:31,152+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= monitoring.VmAnalyzer] (DefaultQuartzScheduler1) [27fac647] VM '3f57e66= 9-5e4c-4d10-85cc-d573004a099d'(Oracle=5FSECONDARY) was unexpectedly det= ected as 'MigratingTo' on VDS 'd569c2dd-8f30-4878-8aea-858db285cf69'(gi= nger.local.systea.fr) (expected on 'ce3938b1-b23f-4d22-840a-f17d7cd87bb= 1') 2018-02-12 16:46:31,152+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= monitoring.VmAnalyzer] (DefaultQuartzScheduler1) [27fac647] VM '3f57e66= 9-5e4c-4d10-85cc-d573004a099d' is migrating to VDS 'd569c2dd-8f30-4878-= 8aea-858db285cf69'(ginger.local.systea.fr) ignoring it in the refresh u= ntil migration is done .... 2018-02-12 16:46:41,631+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= monitoring.VmAnalyzer] (ForkJoinPool-1-worker-11) [] VM '3f57e669-5e4c-= 4d10-85cc-d573004a099d' was reported as Down on VDS 'ce3938b1-b23f-4d22= -840a-f17d7cd87bb1'(victor.local.systea.fr) 2018-02-12 16:46:41,632+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= vdsbroker.DestroyVDSCommand] (ForkJoinPool-1-worker-11) [] START, Destr= oyVDSCommand(HostName =3D victor.local.systea.fr, DestroyVmVDSCommandPa= rameters:{runAsync=3D'true', hostId=3D'ce3938b1-b23f-4d22-840a-f17d7cd8= 7bb1', vmId=3D'3f57e669-5e4c-4d10-85cc-d573004a099d', force=3D'false', = secondsToWait=3D'0', gracefully=3D'false', reason=3D'', ignoreNoVm=3D't= rue'}), log id: 560eca57 2018-02-12 16:46:41,650+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= vdsbroker.DestroyVDSCommand] (ForkJoinPool-1-worker-11) [] FINISH, Dest= royVDSCommand, log id: 560eca57 2018-02-12 16:46:41,650+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= monitoring.VmAnalyzer] (ForkJoinPool-1-worker-11) [] VM '3f57e669-5e4c-= 4d10-85cc-d573004a099d'(Oracle=5FSECONDARY) moved from 'MigratingFrom' = --> 'Down' 2018-02-12 16:46:41,651+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= monitoring.VmAnalyzer] (ForkJoinPool-1-worker-11) [] Handing over VM '3= f57e669-5e4c-4d10-85cc-d573004a099d'(Oracle=5FSECONDARY) to Host 'd569c= 2dd-8f30-4878-8aea-858db285cf69'. Setting VM to status 'MigratingTo' 2018-02-12 16:46:42,163+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= monitoring.VmAnalyzer] (ForkJoinPool-1-worker-4) [] VM '3f57e669-5e4c-4= d10-85cc-d573004a099d'(Oracle=5FSECONDARY) moved from 'MigratingTo' -->= 'Up' 2018-02-12 16:46:42,169+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= vdsbroker.MigrateStatusVDSCommand] (ForkJoinPool-1-worker-4) [] START, = MigrateStatusVDSCommand(HostName =3D ginger.local.systea.fr, MigrateSta= tusVDSCommandParameters:{runAsync=3D'true', hostId=3D'd569c2dd-8f30-487= 8-8aea-858db285cf69', vmId=3D'3f57e669-5e4c-4d10-85cc-d573004a099d'}), = log id: 7a25c281 2018-02-12 16:46:42,174+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= vdsbroker.MigrateStatusVDSCommand] (ForkJoinPool-1-worker-4) [] FINISH,= MigrateStatusVDSCommand, log id: 7a25c281 2018-02-12 16:46:42,194+01 INFO =C2=A0[org.ovirt.engine.core.dal.dbbrok= er.auditloghandling.AuditLogDirector] (ForkJoinPool-1-worker-4) [] EVEN= T=5FID: VM=5FMIGRATION=5FDONE(63), Correlation ID: 2f712024-5982-46a8-8= 2c8-fd8293da5725, Job ID: 4bd19aa9-cc99-4d02-884e-5a1e857a7738, Call St= ack: null, Custom ID: null, Custom Event ID: -1, Message: Migration com= pleted (VM: Oracle=5FSECONDARY, Source: victor.local.systea.fr, Destina= tion: ginger.local.systea.fr, Duration: 11 seconds, Total: 11 seconds, = Actual downtime: (N/A)) 2018-02-12 16:46:42,201+01 INFO =C2=A0[org.ovirt.engine.core.bll.Migrat= eVmToServerCommand] (ForkJoinPool-1-worker-4) [] Lock freed to object '= EngineLock:{exclusiveLocks=3D'[3f57e669-5e4c-4d10-85cc-d573004a099d=3DV= M]', sharedLocks=3D''}' 2018-02-12 16:46:42,203+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= vdsbroker.FullListVDSCommand] (ForkJoinPool-1-worker-4) [] START, FullL= istVDSCommand(HostName =3D ginger.local.systea.fr, FullListVDSCommandPa= rameters:{runAsync=3D'true', hostId=3D'd569c2dd-8f30-4878-8aea-858db285= cf69', vmIds=3D'[3f57e669-5e4c-4d10-85cc-d573004a099d]'}), log id: 7cc6= 5298 2018-02-12 16:46:42,254+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= vdsbroker.FullListVDSCommand] (ForkJoinPool-1-worker-4) [] FINISH, Full= ListVDSCommand, return: [{acpiEnable=3Dtrue, emulatedMachine=3Dpc-i440f= x-rhel7.3.0, afterMigrationStatus=3D, tabletEnable=3Dtrue, pid=3D18748,= guestDiskMapping=3D{}, transparentHugePages=3Dtrue, timeOffset=3D0, cp= uType=3DNehalem, smp=3D2, guestNumaNodes=3D[Ljava.lang.Object;@760085fd= , custom=3D{device=5Ffbddd528-7d93-49c6-a286-180e021cb274device=5F879c9= 3ab-4df1-435c-af02-565039fcc254=3DVmDevice:{id=3D'VmDeviceId:{deviceId=3D= '879c93ab-4df1-435c-af02-565039fcc254', vmId=3D'3f57e669-5e4c-4d10-85cc= -d573004a099d'}', device=3D'unix', type=3D'CHANNEL', bootOrder=3D'0', s= pecParams=3D'[]', address=3D'{bus=3D0, controller=3D0, type=3Dvirtio-se= rial, port=3D1}', managed=3D'false', plugged=3D'true', readOnly=3D'fals= e', deviceAlias=3D'channel0', customProperties=3D'[]', snapshotId=3D'nu= ll', logicalName=3D'null', hostDevice=3D'null'}, device=5Ffbddd528-7d93= -49c6-a286-180e021cb274device=5F879c93ab-4df1-435c-af02-565039fcc254dev= ice=5F8945f61a-abbe-4156-8485-a4aa6f1908dbdevice=5F017b5e59-01c4-4aac-b= f0c-b5d9557284d6=3DVmDevice:{id=3D'VmDeviceId:{deviceId=3D'017b5e59-01c= 4-4aac-bf0c-b5d9557284d6', vmId=3D'3f57e669-5e4c-4d10-85cc-d573004a099d= '}', device=3D'tablet', type=3D'UNKNOWN', bootOrder=3D'0', specParams=3D= '[]', address=3D'{bus=3D0, type=3Dusb, port=3D1}', managed=3D'false', p= lugged=3D'true', readOnly=3D'false', deviceAlias=3D'input0', customProp= erties=3D'[]', snapshotId=3D'null', logicalName=3D'null', hostDevice=3D= 'null'}, device=5Ffbddd528-7d93-49c6-a286-180e021cb274=3DVmDevice:{id=3D= 'VmDeviceId:{deviceId=3D'fbddd528-7d93-49c6-a286-180e021cb274', vmId=3D= '3f57e669-5e4c-4d10-85cc-d573004a099d'}', device=3D'ide', type=3D'CONTR= OLLER', bootOrder=3D'0', specParams=3D'[]', address=3D'{slot=3D0x01, bu= s=3D0x00, domain=3D0x0000, type=3Dpci, function=3D0x1}', managed=3D'fal= se', plugged=3D'true', readOnly=3D'false', deviceAlias=3D'ide', customP= roperties=3D'[]', snapshotId=3D'null', logicalName=3D'null', hostDevice= =3D'null'}, device=5Ffbddd528-7d93-49c6-a286-180e021cb274device=5F879c9= 3ab-4df1-435c-af02-565039fcc254device=5F8945f61a-abbe-4156-8485-a4aa6f1= 908db=3DVmDevice:{id=3D'VmDeviceId:{deviceId=3D'8945f61a-abbe-4156-8485= -a4aa6f1908db', vmId=3D'3f57e669-5e4c-4d10-85cc-d573004a099d'}', device= =3D'unix', type=3D'CHANNEL', bootOrder=3D'0', specParams=3D'[]', addres= s=3D'{bus=3D0, controller=3D0, type=3Dvirtio-serial, port=3D2}', manage= d=3D'false', plugged=3D'true', readOnly=3D'false', deviceAlias=3D'chann= el1', customProperties=3D'[]', snapshotId=3D'null', logicalName=3D'null= ', hostDevice=3D'null'}}, vmType=3Dkvm, memSize=3D8192, smpCoresPerSock= et=3D1, vmName=3DOracle=5FSECONDARY, nice=3D0, status=3DUp, maxMemSize=3D= 32768, bootMenuEnable=3Dfalse, vmId=3D3f57e669-5e4c-4d10-85cc-d573004a0= 99d, numOfIoThreads=3D2, smpThreadsPerCore=3D1, smartcardEnable=3Dfalse= , maxMemSlots=3D16, kvmEnable=3Dtrue, pitReinjection=3Dfalse, displayNe= twork=3Dovirtmgmt, devices=3D[Ljava.lang.Object;@2e4d3dd3, memGuarantee= dSize=3D8192, maxVCpus=3D16, clientIp=3D, statusTime=3D4304259600, disp= lay=3Dvnc}], log id: 7cc65298 2018-02-12 16:46:42,257+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= monitoring.VmDevicesMonitoring] (ForkJoinPool-1-worker-4) [] Received a= vnc Device without an address when processing VM 3f57e669-5e4c-4d10-85= cc-d573004a099d devices, skipping device: {device=3Dvnc, specParams=3D{= displayNetwork=3Dovirtmgmt, keyMap=3Dfr, displayIp=3D192.168.0.5}, type= =3Dgraphics, deviceId=3D813957b1-446a-4e88-9e40-9fe76d2c442d, port=3D59= 01} 2018-02-12 16:46:42,257+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= monitoring.VmDevicesMonitoring] (ForkJoinPool-1-worker-4) [] Received a= lease Device without an address when processing VM 3f57e669-5e4c-4d10-= 85cc-d573004a099d devices, skipping device: {lease=5Fid=3D3f57e669-5e4c= -4d10-85cc-d573004a099d, sd=5Fid=3D1e51cecc-eb2e-47d0-b185-920fdc7afa16= , deviceId=3D{uuid=3Da09949aa-5642-4b6d-94a4-8b0d04257be5}, offset=3D62= 91456, device=3Dlease, path=3D/rhev/data-center/mnt/glusterSD/192.168.0= .6:=5FDATA01/1e51cecc-eb2e-47d0-b185-920fdc7afa16/dom=5Fmd/xleases, typ= e=3Dlease} 2018-02-12 16:46:46,260+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= vdsbroker.FullListVDSCommand] (DefaultQuartzScheduler5) [7fcb200a] FINI= SH, FullListVDSCommand, return: [{acpiEnable=3Dtrue, emulatedMachine=3D= pc-i440fx-rhel7.3.0, afterMigrationStatus=3D, tabletEnable=3Dtrue, pid=3D= 18748, guestDiskMapping=3D{0QEMU=5FQEMU=5FHARDDISK=5Fd890fa68-fba4-4f49= -9=3D{name=3D/dev/sda}, QEMU=5FDVD-ROM=5FQM00003=3D{name=3D/dev/sr0}}, = transparentHugePages=3Dtrue, timeOffset=3D0, cpuType=3DNehalem, smp=3D2= , guestNumaNodes=3D[Ljava.lang.Object;@77951faf, custom=3D{device=5Ffbd= dd528-7d93-49c6-a286-180e021cb274device=5F879c93ab-4df1-435c-af02-56503= 9fcc254=3DVmDevice:{id=3D'VmDeviceId:{deviceId=3D'879c93ab-4df1-435c-af= 02-565039fcc254', vmId=3D'3f57e669-5e4c-4d10-85cc-d573004a099d'}', devi= ce=3D'unix', type=3D'CHANNEL', bootOrder=3D'0', specParams=3D'[]', addr= ess=3D'{bus=3D0, controller=3D0, type=3Dvirtio-serial, port=3D1}', mana= ged=3D'false', plugged=3D'true', readOnly=3D'false', deviceAlias=3D'cha= nnel0', customProperties=3D'[]', snapshotId=3D'null', logicalName=3D'nu= ll', hostDevice=3D'null'}, device=5Ffbddd528-7d93-49c6-a286-180e021cb27= 4device=5F879c93ab-4df1-435c-af02-565039fcc254device=5F8945f61a-abbe-41= 56-8485-a4aa6f1908dbdevice=5F017b5e59-01c4-4aac-bf0c-b5d9557284d6=3DVmD= evice:{id=3D'VmDeviceId:{deviceId=3D'017b5e59-01c4-4aac-bf0c-b5d9557284= d6', vmId=3D'3f57e669-5e4c-4d10-85cc-d573004a099d'}', device=3D'tablet'= , type=3D'UNKNOWN', bootOrder=3D'0', specParams=3D'[]', address=3D'{bus= =3D0, type=3Dusb, port=3D1}', managed=3D'false', plugged=3D'true', read= Only=3D'false', deviceAlias=3D'input0', customProperties=3D'[]', snapsh= otId=3D'null', logicalName=3D'null', hostDevice=3D'null'}, device=5Ffbd= dd528-7d93-49c6-a286-180e021cb274=3DVmDevice:{id=3D'VmDeviceId:{deviceI= d=3D'fbddd528-7d93-49c6-a286-180e021cb274', vmId=3D'3f57e669-5e4c-4d10-= 85cc-d573004a099d'}', device=3D'ide', type=3D'CONTROLLER', bootOrder=3D= '0', specParams=3D'[]', address=3D'{slot=3D0x01, bus=3D0x00, domain=3D0= x0000, type=3Dpci, function=3D0x1}', managed=3D'false', plugged=3D'true= ', readOnly=3D'false', deviceAlias=3D'ide', customProperties=3D'[]', sn= apshotId=3D'null', logicalName=3D'null', hostDevice=3D'null'}, device=5F= fbddd528-7d93-49c6-a286-180e021cb274device=5F879c93ab-4df1-435c-af02-56= 5039fcc254device=5F8945f61a-abbe-4156-8485-a4aa6f1908db=3DVmDevice:{id=3D= 'VmDeviceId:{deviceId=3D'8945f61a-abbe-4156-8485-a4aa6f1908db', vmId=3D= '3f57e669-5e4c-4d10-85cc-d573004a099d'}', device=3D'unix', type=3D'CHAN= NEL', bootOrder=3D'0', specParams=3D'[]', address=3D'{bus=3D0, controll= er=3D0, type=3Dvirtio-serial, port=3D2}', managed=3D'false', plugged=3D= 'true', readOnly=3D'false', deviceAlias=3D'channel1', customProperties=3D= '[]', snapshotId=3D'null', logicalName=3D'null', hostDevice=3D'null'}},= vmType=3Dkvm, memSize=3D8192, smpCoresPerSocket=3D1, vmName=3DOracle=5F= SECONDARY, nice=3D0, status=3DUp, maxMemSize=3D32768, bootMenuEnable=3D= false, vmId=3D3f57e669-5e4c-4d10-85cc-d573004a099d, numOfIoThreads=3D2,= smpThreadsPerCore=3D1, smartcardEnable=3Dfalse, maxMemSlots=3D16, kvmE= nable=3Dtrue, pitReinjection=3Dfalse, displayNetwork=3Dovirtmgmt, devic= es=3D[Ljava.lang.Object;@286410fd, memGuaranteedSize=3D8192, maxVCpus=3D= 16, clientIp=3D, statusTime=3D4304263620, display=3Dvnc}], log id: 58cd= ef4c 2018-02-12 16:46:46,267+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= monitoring.VmDevicesMonitoring] (DefaultQuartzScheduler5) [7fcb200a] Re= ceived a vnc Device without an address when processing VM 3f57e669-5e4c= -4d10-85cc-d573004a099d devices, skipping device: {device=3Dvnc, specPa= rams=3D{displayNetwork=3Dovirtmgmt, keyMap=3Dfr, displayIp=3D192.168.0.= 5}, type=3Dgraphics, deviceId=3D813957b1-446a-4e88-9e40-9fe76d2c442d, p= ort=3D5901} 2018-02-12 16:46:46,268+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= monitoring.VmDevicesMonitoring] (DefaultQuartzScheduler5) [7fcb200a] Re= ceived a lease Device without an address when processing VM 3f57e669-5e= 4c-4d10-85cc-d573004a099d devices, skipping device: {lease=5Fid=3D3f57e= 669-5e4c-4d10-85cc-d573004a099d, sd=5Fid=3D1e51cecc-eb2e-47d0-b185-920f= dc7afa16, deviceId=3D{uuid=3Da09949aa-5642-4b6d-94a4-8b0d04257be5}, off= set=3D6291456, device=3Dlease, path=3D/rhev/data-center/mnt/glusterSD/1= 92.168.0.6:=5FDATA01/1e51cecc-eb2e-47d0-b185-920fdc7afa16/dom=5Fmd/xlea= ses, type=3Dlease} =C2=A0 For the VM with 2 vdisks we see : 2018-02-12 16:49:06,112+01 INFO =C2=A0[org.ovirt.engine.core.bll.Migrat= eVmToServerCommand] (default task-50) [92b5af33-cb87-4142-b8fe-8b838dd7= 458e] Lock Acquired to object 'EngineLock:{exclusiveLocks=3D'[f7d4ec12-= 627a-4b83-b59e-886400d55474=3DVM]', sharedLocks=3D''}' 2018-02-12 16:49:06,407+01 INFO =C2=A0[org.ovirt.engine.core.bll.Migrat= eVmToServerCommand] (org.ovirt.thread.pool-6-thread-49) [92b5af33-cb87-= 4142-b8fe-8b838dd7458e] Running command: MigrateVmToServerCommand inter= nal: false. Entities affected : =C2=A0ID: f7d4ec12-627a-4b83-b59e-88640= 0d55474 Type: VMAction group MIGRATE=5FVM with role type USER 2018-02-12 16:49:06,712+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= MigrateVDSCommand] (org.ovirt.thread.pool-6-thread-49) [92b5af33-cb87-4= 142-b8fe-8b838dd7458e] START, MigrateVDSCommand( MigrateVDSCommandParam= eters:{runAsync=3D'true', hostId=3D'd569c2dd-8f30-4878-8aea-858db285cf6= 9', vmId=3D'f7d4ec12-627a-4b83-b59e-886400d55474', srcHost=3D'192.168.0= .5', dstVdsId=3D'ce3938b1-b23f-4d22-840a-f17d7cd87bb1', dstHost=3D'192.= 168.0.6:54321', migrationMethod=3D'ONLINE', tunnelMigration=3D'false', = migrationDowntime=3D'0', autoConverge=3D'true', migrateCompressed=3D'fa= lse', consoleAddress=3D'null', maxBandwidth=3D'500', enableGuestEvents=3D= 'true', maxIncomingMigrations=3D'2', maxOutgoingMigrations=3D'2', conve= rgenceSchedule=3D'[init=3D[{name=3DsetDowntime, params=3D[100]}], stall= ing=3D[{limit=3D1, action=3D{name=3DsetDowntime, params=3D[150]}}, {lim= it=3D2, action=3D{name=3DsetDowntime, params=3D[200]}}, {limit=3D3, act= ion=3D{name=3DsetDowntime, params=3D[300]}}, {limit=3D4, action=3D{name= =3DsetDowntime, params=3D[400]}}, {limit=3D6, action=3D{name=3DsetDownt= ime, params=3D[500]}}, {limit=3D-1, action=3D{name=3Dabort, params=3D[]= }}]]'}), log id: 3702a9e0 2018-02-12 16:49:06,713+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= vdsbroker.MigrateBrokerVDSCommand] (org.ovirt.thread.pool-6-thread-49) = [92b5af33-cb87-4142-b8fe-8b838dd7458e] START, MigrateBrokerVDSCommand(H= ostName =3D ginger.local.systea.fr, MigrateVDSCommandParameters:{runAsy= nc=3D'true', hostId=3D'd569c2dd-8f30-4878-8aea-858db285cf69', vmId=3D'f= 7d4ec12-627a-4b83-b59e-886400d55474', srcHost=3D'192.168.0.5', dstVdsId= =3D'ce3938b1-b23f-4d22-840a-f17d7cd87bb1', dstHost=3D'192.168.0.6:54321= ', migrationMethod=3D'ONLINE', tunnelMigration=3D'false', migrationDown= time=3D'0', autoConverge=3D'true', migrateCompressed=3D'false', console= Address=3D'null', maxBandwidth=3D'500', enableGuestEvents=3D'true', max= IncomingMigrations=3D'2', maxOutgoingMigrations=3D'2', convergenceSched= ule=3D'[init=3D[{name=3DsetDowntime, params=3D[100]}], stalling=3D[{lim= it=3D1, action=3D{name=3DsetDowntime, params=3D[150]}}, {limit=3D2, act= ion=3D{name=3DsetDowntime, params=3D[200]}}, {limit=3D3, action=3D{name= =3DsetDowntime, params=3D[300]}}, {limit=3D4, action=3D{name=3DsetDownt= ime, params=3D[400]}}, {limit=3D6, action=3D{name=3DsetDowntime, params= =3D[500]}}, {limit=3D-1, action=3D{name=3Dabort, params=3D[]}}]]'}), lo= g id: 1840069c 2018-02-12 16:49:06,724+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= vdsbroker.MigrateBrokerVDSCommand] (org.ovirt.thread.pool-6-thread-49) = [92b5af33-cb87-4142-b8fe-8b838dd7458e] FINISH, MigrateBrokerVDSCommand,= log id: 1840069c 2018-02-12 16:49:06,732+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= MigrateVDSCommand] (org.ovirt.thread.pool-6-thread-49) [92b5af33-cb87-4= 142-b8fe-8b838dd7458e] FINISH, MigrateVDSCommand, return: MigratingFrom= , log id: 3702a9e0 2018-02-12 16:49:06,753+01 INFO =C2=A0[org.ovirt.engine.core.dal.dbbrok= er.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-4= 9) [92b5af33-cb87-4142-b8fe-8b838dd7458e] EVENT=5FID: VM=5FMIGRATION=5F= START(62), Correlation ID: 92b5af33-cb87-4142-b8fe-8b838dd7458e, Job ID= : f4f54054-f7c8-4481-8eda-d5a15c383061, Call Stack: null, Custom ID: nu= ll, Custom Event ID: -1, Message: Migration started (VM: Oracle=5FPRIMA= RY, Source: ginger.local.systea.fr, Destination: victor.local.systea.fr= , User: admin@internal-authz). ... 2018-02-12 16:49:16,453+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= monitoring.VmsStatisticsFetcher] (DefaultQuartzScheduler4) [162a5bc3] F= etched 2 VMs from VDS 'ce3938b1-b23f-4d22-840a-f17d7cd87bb1' 2018-02-12 16:49:16,455+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= monitoring.VmAnalyzer] (DefaultQuartzScheduler4) [162a5bc3] VM 'f7d4ec1= 2-627a-4b83-b59e-886400d55474'(Oracle=5FPRIMARY) was unexpectedly detec= ted as 'MigratingTo' on VDS 'ce3938b1-b23f-4d22-840a-f17d7cd87bb1'(vict= or.local.systea.fr) (expected on 'd569c2dd-8f30-4878-8aea-858db285cf69'= ) 2018-02-12 16:49:16,455+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= monitoring.VmAnalyzer] (DefaultQuartzScheduler4) [162a5bc3] VM 'f7d4ec1= 2-627a-4b83-b59e-886400d55474' is migrating to VDS 'ce3938b1-b23f-4d22-= 840a-f17d7cd87bb1'(victor.local.systea.fr) ignoring it in the refresh u= ntil migration is done ... 2018-02-12 16:49:31,484+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= monitoring.VmAnalyzer] (DefaultQuartzScheduler5) [11a7619a] VM 'f7d4ec1= 2-627a-4b83-b59e-886400d55474'(Oracle=5FPRIMARY) was unexpectedly detec= ted as 'MigratingTo' on VDS 'ce3938b1-b23f-4d22-840a-f17d7cd87bb1'(vict= or.local.systea.fr) (expected on 'd569c2dd-8f30-4878-8aea-858db285cf69'= ) 2018-02-12 16:49:31,484+01 INFO =C2=A0[org.ovirt.engine.core.vdsbroker.= monitoring.VmAnalyzer] (DefaultQuartzScheduler5) [11a7619a] VM 'f7d4ec1= 2-627a-4b83-b59e-886400d55474' is migrating to VDS 'ce3938b1-b23f-4d22-= 840a-f17d7cd87bb1'(victor.local.systea.fr) ignoring it in the refresh u= ntil migration is done =C2=A0 and so on, last lines repeated indefinitly for hours since we poweroff = the VM... Is this something known ? Any idea about that ? Thanks -- Cordialement, Frank Soyer =C2=A0 ------=_=-_OpenGroupware_org_NGMime-15477-1518516470.384163-4------ Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: quoted-printable Content-Length: 30330 <html>Hi all,<br />I discovered yesterday a problem when migrating VM w= ith more than one vdisk.<br />On our test servers (oVirt4.1, shared sto= rage with Gluster), I created 2 VMs needed for a test, from a template = with a 20G vdisk. On this VMs I added a 100G vdisk (for this tests I di= dn't want to waste time to extend the existing vdisks... But I lost tim= e finally...). The VMs with the 2 vdisks works well.<br />Now I saw som= e updates waiting on the host. I tried to put it in maintenance... But = it stopped on the two VM. They were marked "migrating", but no more acc= essible. Other (small) VMs with only 1 vdisk was migrated without probl= em at the same time.<br />I saw that a kvm process for the (big) VMs wa= s launched on the source AND destination host, but after tens of minute= s, the migration and the VMs was always freezed. I tried to cancel the = migration for the VMs : failed. The only way to stop it was to poweroff= the VMs : the kvm process died on the 2 hosts and the GUI alerted on a= failed migration.<br />In doubt, I tried to delete the second vdisk on= one of this VMs : it migrates then without error ! And no access probl= em.<br />I tried to extend the first vdisk of the second VM, the delete= the second vdisk : it migrates now without problem ! = <br /><br />So after another test with a VM with 2 vdisks, I can say th= at this blocked the migration process :(<br /><br />In engine.log, for = a VMs with 1 vdisk migrating well, we see :<blockquote>2018-02-12 16:46= :29,705+01 INFO [org.ovirt.engine.core.bll.MigrateVmToServerComma= nd] (default task-28) [2f712024-5982-46a8-82c8-fd8293da5725] Lock Acqui= red to object 'EngineLock:{exclusiveLocks=3D'[3f57e669-5e4c-4d10-85cc-d= 573004a099d=3DVM]', sharedLocks=3D''}'<br />2018-02-12 16:46:29,955+01 = INFO [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (org.ov= irt.thread.pool-6-thread-32) [2f712024-5982-46a8-82c8-fd8293da5725] Run= ning command: MigrateVmToServerCommand internal: false. Entities affect= ed : ID: 3f57e669-5e4c-4d10-85cc-d573004a099d Type: VMAction grou= p MIGRATE=5FVM with role type USER<br />2018-02-12 16:46:30,261+01 INFO= [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (org.ovirt.t= hread.pool-6-thread-32) [2f712024-5982-46a8-82c8-fd8293da5725] START, M= igrateVDSCommand( MigrateVDSCommandParameters:{runAsync=3D'true', hostI= d=3D'ce3938b1-b23f-4d22-840a-f17d7cd87bb1', vmId=3D'3f57e669-5e4c-4d10-= 85cc-d573004a099d', srcHost=3D'192.168.0.6', dstVdsId=3D'd569c2dd-8f30-= 4878-8aea-858db285cf69', dstHost=3D'192.168.0.5:54321', migrationMethod= =3D'ONLINE', tunnelMigration=3D'false', migrationDowntime=3D'0', autoCo= nverge=3D'true', migrateCompressed=3D'false', consoleAddress=3D'null', = maxBandwidth=3D'500', enableGuestEvents=3D'true', maxIncomingMigrations= =3D'2', maxOutgoingMigrations=3D'2', convergenceSchedule=3D'[init=3D[{n= ame=3DsetDowntime, params=3D[100]}], stalling=3D[{limit=3D1, action=3D{= name=3DsetDowntime, params=3D[150]}}, {limit=3D2, action=3D{name=3DsetD= owntime, params=3D[200]}}, {limit=3D3, action=3D{name=3DsetDowntime, pa= rams=3D[300]}}, {limit=3D4, action=3D{name=3DsetDowntime, params=3D[400= ]}}, {limit=3D6, action=3D{name=3DsetDowntime, params=3D[500]}}, {limit= =3D-1, action=3D{name=3Dabort, params=3D[]}}]]'}), log id: 14f61ee0<br = />2018-02-12 16:46:30,262+01 INFO [org.ovirt.engine.core.vdsbroke= r.vdsbroker.MigrateBrokerVDSCommand] (org.ovirt.thread.pool-6-thread-32= ) [2f712024-5982-46a8-82c8-fd8293da5725] START, MigrateBrokerVDSCommand= (HostName =3D victor.local.systea.fr, MigrateVDSCommandParameters:{runA= sync=3D'true', hostId=3D'ce3938b1-b23f-4d22-840a-f17d7cd87bb1', vmId=3D= '3f57e669-5e4c-4d10-85cc-d573004a099d', srcHost=3D'192.168.0.6', dstVds= Id=3D'd569c2dd-8f30-4878-8aea-858db285cf69', dstHost=3D'192.168.0.5:543= 21', migrationMethod=3D'ONLINE', tunnelMigration=3D'false', migrationDo= wntime=3D'0', autoConverge=3D'true', migrateCompressed=3D'false', conso= leAddress=3D'null', maxBandwidth=3D'500', enableGuestEvents=3D'true', m= axIncomingMigrations=3D'2', maxOutgoingMigrations=3D'2', convergenceSch= edule=3D'[init=3D[{name=3DsetDowntime, params=3D[100]}], stalling=3D[{l= imit=3D1, action=3D{name=3DsetDowntime, params=3D[150]}}, {limit=3D2, a= ction=3D{name=3DsetDowntime, params=3D[200]}}, {limit=3D3, action=3D{na= me=3DsetDowntime, params=3D[300]}}, {limit=3D4, action=3D{name=3DsetDow= ntime, params=3D[400]}}, {limit=3D6, action=3D{name=3DsetDowntime, para= ms=3D[500]}}, {limit=3D-1, action=3D{name=3Dabort, params=3D[]}}]]'}), = log id: 775cd381<br />2018-02-12 16:46:30,277+01 INFO [org.ovirt.= engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (org.ovirt.thr= ead.pool-6-thread-32) [2f712024-5982-46a8-82c8-fd8293da5725] FINISH, Mi= grateBrokerVDSCommand, log id: 775cd381<br />2018-02-12 16:46:30,285+01= INFO [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (org.ov= irt.thread.pool-6-thread-32) [2f712024-5982-46a8-82c8-fd8293da5725] FIN= ISH, MigrateVDSCommand, return: MigratingFrom, log id: 14f61ee0<br />20= 18-02-12 16:46:30,301+01 INFO [org.ovirt.engine.core.dal.dbbroker= .auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-32)= [2f712024-5982-46a8-82c8-fd8293da5725] EVENT=5FID: VM=5FMIGRATION=5FST= ART(62), Correlation ID: 2f712024-5982-46a8-82c8-fd8293da5725, Job ID: = 4bd19aa9-cc99-4d02-884e-5a1e857a7738, Call Stack: null, Custom ID: null= , Custom Event ID: -1, Message: Migration started (VM: Oracle=5FSECONDA= RY, Source: victor.local.systea.fr, Destination: ginger.local.systea.fr= , User: admin@internal-authz).<br />2018-02-12 16:46:31,106+01 INFO &nb= sp;[org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVDSCommand] (Defa= ultQuartzScheduler9) [54a65b66] START, FullListVDSCommand(HostName =3D = victor.local.systea.fr, FullListVDSCommandParameters:{runAsync=3D'true'= , hostId=3D'ce3938b1-b23f-4d22-840a-f17d7cd87bb1', vmIds=3D'[3f57e669-5= e4c-4d10-85cc-d573004a099d]'}), log id: 54b4b435<br />2018-02-12 16:46:= 31,147+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.FullLis= tVDSCommand] (DefaultQuartzScheduler9) [54a65b66] FINISH, FullListVDSCo= mmand, return: [{acpiEnable=3Dtrue, emulatedMachine=3Dpc-i440fx-rhel7.3= .0, tabletEnable=3Dtrue, pid=3D1493, guestDiskMapping=3D{0QEMU=5FQEMU=5F= HARDDISK=5Fd890fa68-fba4-4f49-9=3D{name=3D/dev/sda}, QEMU=5FDVD-ROM=5FQ= M00003=3D{name=3D/dev/sr0}}, transparentHugePages=3Dtrue, timeOffset=3D= 0, cpuType=3DNehalem, smp=3D2, pauseCode=3DNOERR, guestNumaNodes=3D[Lja= va.lang.Object;@1d9042cd, smartcardEnable=3Dfalse, custom=3D{device=5Ff= bddd528-7d93-49c6-a286-180e021cb274device=5F879c93ab-4df1-435c-af02-565= 039fcc254=3DVmDevice:{id=3D'VmDeviceId:{deviceId=3D'879c93ab-4df1-435c-= af02-565039fcc254', vmId=3D'3f57e669-5e4c-4d10-85cc-d573004a099d'}', de= vice=3D'unix', type=3D'CHANNEL', bootOrder=3D'0', specParams=3D'[]', ad= dress=3D'{bus=3D0, controller=3D0, type=3Dvirtio-serial, port=3D1}', ma= naged=3D'false', plugged=3D'true', readOnly=3D'false', deviceAlias=3D'c= hannel0', customProperties=3D'[]', snapshotId=3D'null', logicalName=3D'= null', hostDevice=3D'null'}, device=5Ffbddd528-7d93-49c6-a286-180e021cb= 274device=5F879c93ab-4df1-435c-af02-565039fcc254device=5F8945f61a-abbe-= 4156-8485-a4aa6f1908dbdevice=5F017b5e59-01c4-4aac-bf0c-b5d9557284d6=3DV= mDevice:{id=3D'VmDeviceId:{deviceId=3D'017b5e59-01c4-4aac-bf0c-b5d95572= 84d6', vmId=3D'3f57e669-5e4c-4d10-85cc-d573004a099d'}', device=3D'table= t', type=3D'UNKNOWN', bootOrder=3D'0', specParams=3D'[]', address=3D'{b= us=3D0, type=3Dusb, port=3D1}', managed=3D'false', plugged=3D'true', re= adOnly=3D'false', deviceAlias=3D'input0', customProperties=3D'[]', snap= shotId=3D'null', logicalName=3D'null', hostDevice=3D'null'}, device=5Ff= bddd528-7d93-49c6-a286-180e021cb274=3DVmDevice:{id=3D'VmDeviceId:{devic= eId=3D'fbddd528-7d93-49c6-a286-180e021cb274', vmId=3D'3f57e669-5e4c-4d1= 0-85cc-d573004a099d'}', device=3D'ide', type=3D'CONTROLLER', bootOrder=3D= '0', specParams=3D'[]', address=3D'{slot=3D0x01, bus=3D0x00, domain=3D0= x0000, type=3Dpci, function=3D0x1}', managed=3D'false', plugged=3D'true= ', readOnly=3D'false', deviceAlias=3D'ide', customProperties=3D'[]', sn= apshotId=3D'null', logicalName=3D'null', hostDevice=3D'null'}, device=5F= fbddd528-7d93-49c6-a286-180e021cb274device=5F879c93ab-4df1-435c-af02-56= 5039fcc254device=5F8945f61a-abbe-4156-8485-a4aa6f1908db=3DVmDevice:{id=3D= 'VmDeviceId:{deviceId=3D'8945f61a-abbe-4156-8485-a4aa6f1908db', vmId=3D= '3f57e669-5e4c-4d10-85cc-d573004a099d'}', device=3D'unix', type=3D'CHAN= NEL', bootOrder=3D'0', specParams=3D'[]', address=3D'{bus=3D0, controll= er=3D0, type=3Dvirtio-serial, port=3D2}', managed=3D'false', plugged=3D= 'true', readOnly=3D'false', deviceAlias=3D'channel1', customProperties=3D= '[]', snapshotId=3D'null', logicalName=3D'null', hostDevice=3D'null'}},= vmType=3Dkvm, memSize=3D8192, smpCoresPerSocket=3D1, vmName=3DOracle=5F= SECONDARY, nice=3D0, status=3DMigration Source, maxMemSize=3D32768, boo= tMenuEnable=3Dfalse, vmId=3D3f57e669-5e4c-4d10-85cc-d573004a099d, numOf= IoThreads=3D2, smpThreadsPerCore=3D1, memGuaranteedSize=3D8192, kvmEnab= le=3Dtrue, pitReinjection=3Dfalse, displayNetwork=3Dovirtmgmt, devices=3D= [Ljava.lang.Object;@28ae66d7, display=3Dvnc, maxVCpus=3D16, clientIp=3D= , statusTime=3D4299484520, maxMemSlots=3D16}], log id: 54b4b435<br />20= 18-02-12 16:46:31,150+01 INFO [org.ovirt.engine.core.vdsbroker.mo= nitoring.VmsStatisticsFetcher] (DefaultQuartzScheduler1) [27fac647] Fet= ched 3 VMs from VDS 'd569c2dd-8f30-4878-8aea-858db285cf69'<br />2018-02= -12 16:46:31,151+01 INFO [org.ovirt.engine.core.vdsbroker.monitor= ing.VmDevicesMonitoring] (DefaultQuartzScheduler9) [54a65b66] Received = a vnc Device without an address when processing VM 3f57e669-5e4c-4d10-8= 5cc-d573004a099d devices, skipping device: {device=3Dvnc, specParams=3D= {displayNetwork=3Dovirtmgmt, keyMap=3Dfr, displayIp=3D192.168.0.6}, typ= e=3Dgraphics, deviceId=3D813957b1-446a-4e88-9e40-9fe76d2c442d, port=3D5= 901}<br />2018-02-12 16:46:31,151+01 INFO [org.ovirt.engine.core.= vdsbroker.monitoring.VmDevicesMonitoring] (DefaultQuartzScheduler9) [54= a65b66] Received a lease Device without an address when processing VM 3= f57e669-5e4c-4d10-85cc-d573004a099d devices, skipping device: {lease=5F= id=3D3f57e669-5e4c-4d10-85cc-d573004a099d, sd=5Fid=3D1e51cecc-eb2e-47d0= -b185-920fdc7afa16, deviceId=3D{uuid=3Da09949aa-5642-4b6d-94a4-8b0d0425= 7be5}, offset=3D6291456, device=3Dlease, path=3D/rhev/data-center/mnt/g= lusterSD/192.168.0.6:=5FDATA01/1e51cecc-eb2e-47d0-b185-920fdc7afa16/dom= =5Fmd/xleases, type=3Dlease}<br />2018-02-12 16:46:31,152+01 INFO = ;[org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (DefaultQuartz= Scheduler1) [27fac647] VM '3f57e669-5e4c-4d10-85cc-d573004a099d'(Oracle= =5FSECONDARY) was unexpectedly detected as 'MigratingTo' on VDS 'd569c2= dd-8f30-4878-8aea-858db285cf69'(ginger.local.systea.fr) (expected on 'c= e3938b1-b23f-4d22-840a-f17d7cd87bb1')<br />2018-02-12 16:46:31,152+01 I= NFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (Defa= ultQuartzScheduler1) [27fac647] VM '3f57e669-5e4c-4d10-85cc-d573004a099= d' is migrating to VDS 'd569c2dd-8f30-4878-8aea-858db285cf69'(ginger.lo= cal.systea.fr) ignoring it in the refresh until migration is done<br />= ....<br />2018-02-12 16:46:41,631+01 INFO [org.ovirt.engine.core.= vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-11) [] VM '3f57= e669-5e4c-4d10-85cc-d573004a099d' was reported as Down on VDS 'ce3938b1= -b23f-4d22-840a-f17d7cd87bb1'(victor.local.systea.fr)<br />2018-02-12 1= 6:46:41,632+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.De= stroyVDSCommand] (ForkJoinPool-1-worker-11) [] START, DestroyVDSCommand= (HostName =3D victor.local.systea.fr, DestroyVmVDSCommandParameters:{ru= nAsync=3D'true', hostId=3D'ce3938b1-b23f-4d22-840a-f17d7cd87bb1', vmId=3D= '3f57e669-5e4c-4d10-85cc-d573004a099d', force=3D'false', secondsToWait=3D= '0', gracefully=3D'false', reason=3D'', ignoreNoVm=3D'true'}), log id: = 560eca57<br />2018-02-12 16:46:41,650+01 INFO [org.ovirt.engine.c= ore.vdsbroker.vdsbroker.DestroyVDSCommand] (ForkJoinPool-1-worker-11) [= ] FINISH, DestroyVDSCommand, log id: 560eca57<br />2018-02-12 16:46:41,= 650+01 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyze= r] (ForkJoinPool-1-worker-11) [] VM '3f57e669-5e4c-4d10-85cc-d573004a09= 9d'(Oracle=5FSECONDARY) moved from 'MigratingFrom' --> 'Down'<br />2= 018-02-12 16:46:41,651+01 INFO [org.ovirt.engine.core.vdsbroker.m= onitoring.VmAnalyzer] (ForkJoinPool-1-worker-11) [] Handing over VM '3f= 57e669-5e4c-4d10-85cc-d573004a099d'(Oracle=5FSECONDARY) to Host 'd569c2= dd-8f30-4878-8aea-858db285cf69'. Setting VM to status 'MigratingTo'<br = />2018-02-12 16:46:42,163+01 INFO [org.ovirt.engine.core.vdsbroke= r.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-4) [] VM '3f57e669-5e4c= -4d10-85cc-d573004a099d'(Oracle=5FSECONDARY) moved from 'MigratingTo' -= -> 'Up'<br />2018-02-12 16:46:42,169+01 INFO [org.ovirt.engine= .core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (ForkJoinPool-1-work= er-4) [] START, MigrateStatusVDSCommand(HostName =3D ginger.local.syste= a.fr, MigrateStatusVDSCommandParameters:{runAsync=3D'true', hostId=3D'd= 569c2dd-8f30-4878-8aea-858db285cf69', vmId=3D'3f57e669-5e4c-4d10-85cc-d= 573004a099d'}), log id: 7a25c281<br />2018-02-12 16:46:42,174+01 INFO &= nbsp;[org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand= ] (ForkJoinPool-1-worker-4) [] FINISH, MigrateStatusVDSCommand, log id:= 7a25c281<br />2018-02-12 16:46:42,194+01 INFO [org.ovirt.engine.= core.dal.dbbroker.auditloghandling.AuditLogDirector] (ForkJoinPool-1-wo= rker-4) [] EVENT=5FID: VM=5FMIGRATION=5FDONE(63), Correlation ID: 2f712= 024-5982-46a8-82c8-fd8293da5725, Job ID: 4bd19aa9-cc99-4d02-884e-5a1e85= 7a7738, Call Stack: null, Custom ID: null, Custom Event ID: -1, Message= : Migration completed (VM: Oracle=5FSECONDARY, Source: victor.local.sys= tea.fr, Destination: ginger.local.systea.fr, Duration: 11 seconds, Tota= l: 11 seconds, Actual downtime: (N/A))<br />2018-02-12 16:46:42,201+01 = INFO [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (ForkJo= inPool-1-worker-4) [] Lock freed to object 'EngineLock:{exclusiveLocks=3D= '[3f57e669-5e4c-4d10-85cc-d573004a099d=3DVM]', sharedLocks=3D''}'<br />= 2018-02-12 16:46:42,203+01 INFO [org.ovirt.engine.core.vdsbroker.= vdsbroker.FullListVDSCommand] (ForkJoinPool-1-worker-4) [] START, FullL= istVDSCommand(HostName =3D ginger.local.systea.fr, FullListVDSCommandPa= rameters:{runAsync=3D'true', hostId=3D'd569c2dd-8f30-4878-8aea-858db285= cf69', vmIds=3D'[3f57e669-5e4c-4d10-85cc-d573004a099d]'}), log id: 7cc6= 5298<br />2018-02-12 16:46:42,254+01 INFO [org.ovirt.engine.core.= vdsbroker.vdsbroker.FullListVDSCommand] (ForkJoinPool-1-worker-4) [] FI= NISH, FullListVDSCommand, return: [{acpiEnable=3Dtrue, emulatedMachine=3D= pc-i440fx-rhel7.3.0, afterMigrationStatus=3D, tabletEnable=3Dtrue, pid=3D= 18748, guestDiskMapping=3D{}, transparentHugePages=3Dtrue, timeOffset=3D= 0, cpuType=3DNehalem, smp=3D2, guestNumaNodes=3D[Ljava.lang.Object;@760= 085fd, custom=3D{device=5Ffbddd528-7d93-49c6-a286-180e021cb274device=5F= 879c93ab-4df1-435c-af02-565039fcc254=3DVmDevice:{id=3D'VmDeviceId:{devi= ceId=3D'879c93ab-4df1-435c-af02-565039fcc254', vmId=3D'3f57e669-5e4c-4d= 10-85cc-d573004a099d'}', device=3D'unix', type=3D'CHANNEL', bootOrder=3D= '0', specParams=3D'[]', address=3D'{bus=3D0, controller=3D0, type=3Dvir= tio-serial, port=3D1}', managed=3D'false', plugged=3D'true', readOnly=3D= 'false', deviceAlias=3D'channel0', customProperties=3D'[]', snapshotId=3D= 'null', logicalName=3D'null', hostDevice=3D'null'}, device=5Ffbddd528-7= d93-49c6-a286-180e021cb274device=5F879c93ab-4df1-435c-af02-565039fcc254= device=5F8945f61a-abbe-4156-8485-a4aa6f1908dbdevice=5F017b5e59-01c4-4aa= c-bf0c-b5d9557284d6=3DVmDevice:{id=3D'VmDeviceId:{deviceId=3D'017b5e59-= 01c4-4aac-bf0c-b5d9557284d6', vmId=3D'3f57e669-5e4c-4d10-85cc-d573004a0= 99d'}', device=3D'tablet', type=3D'UNKNOWN', bootOrder=3D'0', specParam= s=3D'[]', address=3D'{bus=3D0, type=3Dusb, port=3D1}', managed=3D'false= ', plugged=3D'true', readOnly=3D'false', deviceAlias=3D'input0', custom= Properties=3D'[]', snapshotId=3D'null', logicalName=3D'null', hostDevic= e=3D'null'}, device=5Ffbddd528-7d93-49c6-a286-180e021cb274=3DVmDevice:{= id=3D'VmDeviceId:{deviceId=3D'fbddd528-7d93-49c6-a286-180e021cb274', vm= Id=3D'3f57e669-5e4c-4d10-85cc-d573004a099d'}', device=3D'ide', type=3D'= CONTROLLER', bootOrder=3D'0', specParams=3D'[]', address=3D'{slot=3D0x0= 1, bus=3D0x00, domain=3D0x0000, type=3Dpci, function=3D0x1}', managed=3D= 'false', plugged=3D'true', readOnly=3D'false', deviceAlias=3D'ide', cus= tomProperties=3D'[]', snapshotId=3D'null', logicalName=3D'null', hostDe= vice=3D'null'}, device=5Ffbddd528-7d93-49c6-a286-180e021cb274device=5F8= 79c93ab-4df1-435c-af02-565039fcc254device=5F8945f61a-abbe-4156-8485-a4a= a6f1908db=3DVmDevice:{id=3D'VmDeviceId:{deviceId=3D'8945f61a-abbe-4156-= 8485-a4aa6f1908db', vmId=3D'3f57e669-5e4c-4d10-85cc-d573004a099d'}', de= vice=3D'unix', type=3D'CHANNEL', bootOrder=3D'0', specParams=3D'[]', ad= dress=3D'{bus=3D0, controller=3D0, type=3Dvirtio-serial, port=3D2}', ma= naged=3D'false', plugged=3D'true', readOnly=3D'false', deviceAlias=3D'c= hannel1', customProperties=3D'[]', snapshotId=3D'null', logicalName=3D'= null', hostDevice=3D'null'}}, vmType=3Dkvm, memSize=3D8192, smpCoresPer= Socket=3D1, vmName=3DOracle=5FSECONDARY, nice=3D0, status=3DUp, maxMemS= ize=3D32768, bootMenuEnable=3Dfalse, vmId=3D3f57e669-5e4c-4d10-85cc-d57= 3004a099d, numOfIoThreads=3D2, smpThreadsPerCore=3D1, smartcardEnable=3D= false, maxMemSlots=3D16, kvmEnable=3Dtrue, pitReinjection=3Dfalse, disp= layNetwork=3Dovirtmgmt, devices=3D[Ljava.lang.Object;@2e4d3dd3, memGuar= anteedSize=3D8192, maxVCpus=3D16, clientIp=3D, statusTime=3D4304259600,= display=3Dvnc}], log id: 7cc65298<br />2018-02-12 16:46:42,257+01 INFO= [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring]= (ForkJoinPool-1-worker-4) [] Received a vnc Device without an address = when processing VM 3f57e669-5e4c-4d10-85cc-d573004a099d devices, skippi= ng device: {device=3Dvnc, specParams=3D{displayNetwork=3Dovirtmgmt, key= Map=3Dfr, displayIp=3D192.168.0.5}, type=3Dgraphics, deviceId=3D813957b= 1-446a-4e88-9e40-9fe76d2c442d, port=3D5901}<br />2018-02-12 16:46:42,25= 7+01 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMo= nitoring] (ForkJoinPool-1-worker-4) [] Received a lease Device without = an address when processing VM 3f57e669-5e4c-4d10-85cc-d573004a099d devi= ces, skipping device: {lease=5Fid=3D3f57e669-5e4c-4d10-85cc-d573004a099= d, sd=5Fid=3D1e51cecc-eb2e-47d0-b185-920fdc7afa16, deviceId=3D{uuid=3Da= 09949aa-5642-4b6d-94a4-8b0d04257be5}, offset=3D6291456, device=3Dlease,= path=3D/rhev/data-center/mnt/glusterSD/192.168.0.6:=5FDATA01/1e51cecc-= eb2e-47d0-b185-920fdc7afa16/dom=5Fmd/xleases, type=3Dlease}<br />2018-0= 2-12 16:46:46,260+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbro= ker.FullListVDSCommand] (DefaultQuartzScheduler5) [7fcb200a] FINISH, Fu= llListVDSCommand, return: [{acpiEnable=3Dtrue, emulatedMachine=3Dpc-i44= 0fx-rhel7.3.0, afterMigrationStatus=3D, tabletEnable=3Dtrue, pid=3D1874= 8, guestDiskMapping=3D{0QEMU=5FQEMU=5FHARDDISK=5Fd890fa68-fba4-4f49-9=3D= {name=3D/dev/sda}, QEMU=5FDVD-ROM=5FQM00003=3D{name=3D/dev/sr0}}, trans= parentHugePages=3Dtrue, timeOffset=3D0, cpuType=3DNehalem, smp=3D2, gue= stNumaNodes=3D[Ljava.lang.Object;@77951faf, custom=3D{device=5Ffbddd528= -7d93-49c6-a286-180e021cb274device=5F879c93ab-4df1-435c-af02-565039fcc2= 54=3DVmDevice:{id=3D'VmDeviceId:{deviceId=3D'879c93ab-4df1-435c-af02-56= 5039fcc254', vmId=3D'3f57e669-5e4c-4d10-85cc-d573004a099d'}', device=3D= 'unix', type=3D'CHANNEL', bootOrder=3D'0', specParams=3D'[]', address=3D= '{bus=3D0, controller=3D0, type=3Dvirtio-serial, port=3D1}', managed=3D= 'false', plugged=3D'true', readOnly=3D'false', deviceAlias=3D'channel0'= , customProperties=3D'[]', snapshotId=3D'null', logicalName=3D'null', h= ostDevice=3D'null'}, device=5Ffbddd528-7d93-49c6-a286-180e021cb274devic= e=5F879c93ab-4df1-435c-af02-565039fcc254device=5F8945f61a-abbe-4156-848= 5-a4aa6f1908dbdevice=5F017b5e59-01c4-4aac-bf0c-b5d9557284d6=3DVmDevice:= {id=3D'VmDeviceId:{deviceId=3D'017b5e59-01c4-4aac-bf0c-b5d9557284d6', v= mId=3D'3f57e669-5e4c-4d10-85cc-d573004a099d'}', device=3D'tablet', type= =3D'UNKNOWN', bootOrder=3D'0', specParams=3D'[]', address=3D'{bus=3D0, = type=3Dusb, port=3D1}', managed=3D'false', plugged=3D'true', readOnly=3D= 'false', deviceAlias=3D'input0', customProperties=3D'[]', snapshotId=3D= 'null', logicalName=3D'null', hostDevice=3D'null'}, device=5Ffbddd528-7= d93-49c6-a286-180e021cb274=3DVmDevice:{id=3D'VmDeviceId:{deviceId=3D'fb= ddd528-7d93-49c6-a286-180e021cb274', vmId=3D'3f57e669-5e4c-4d10-85cc-d5= 73004a099d'}', device=3D'ide', type=3D'CONTROLLER', bootOrder=3D'0', sp= ecParams=3D'[]', address=3D'{slot=3D0x01, bus=3D0x00, domain=3D0x0000, = type=3Dpci, function=3D0x1}', managed=3D'false', plugged=3D'true', read= Only=3D'false', deviceAlias=3D'ide', customProperties=3D'[]', snapshotI= d=3D'null', logicalName=3D'null', hostDevice=3D'null'}, device=5Ffbddd5= 28-7d93-49c6-a286-180e021cb274device=5F879c93ab-4df1-435c-af02-565039fc= c254device=5F8945f61a-abbe-4156-8485-a4aa6f1908db=3DVmDevice:{id=3D'VmD= eviceId:{deviceId=3D'8945f61a-abbe-4156-8485-a4aa6f1908db', vmId=3D'3f5= 7e669-5e4c-4d10-85cc-d573004a099d'}', device=3D'unix', type=3D'CHANNEL'= , bootOrder=3D'0', specParams=3D'[]', address=3D'{bus=3D0, controller=3D= 0, type=3Dvirtio-serial, port=3D2}', managed=3D'false', plugged=3D'true= ', readOnly=3D'false', deviceAlias=3D'channel1', customProperties=3D'[]= ', snapshotId=3D'null', logicalName=3D'null', hostDevice=3D'null'}}, vm= Type=3Dkvm, memSize=3D8192, smpCoresPerSocket=3D1, vmName=3DOracle=5FSE= CONDARY, nice=3D0, status=3DUp, maxMemSize=3D32768, bootMenuEnable=3Dfa= lse, vmId=3D3f57e669-5e4c-4d10-85cc-d573004a099d, numOfIoThreads=3D2, s= mpThreadsPerCore=3D1, smartcardEnable=3Dfalse, maxMemSlots=3D16, kvmEna= ble=3Dtrue, pitReinjection=3Dfalse, displayNetwork=3Dovirtmgmt, devices= =3D[Ljava.lang.Object;@286410fd, memGuaranteedSize=3D8192, maxVCpus=3D1= 6, clientIp=3D, statusTime=3D4304263620, display=3Dvnc}], log id: 58cde= f4c<br />2018-02-12 16:46:46,267+01 INFO [org.ovirt.engine.core.v= dsbroker.monitoring.VmDevicesMonitoring] (DefaultQuartzScheduler5) [7fc= b200a] Received a vnc Device without an address when processing VM 3f57= e669-5e4c-4d10-85cc-d573004a099d devices, skipping device: {device=3Dvn= c, specParams=3D{displayNetwork=3Dovirtmgmt, keyMap=3Dfr, displayIp=3D1= 92.168.0.5}, type=3Dgraphics, deviceId=3D813957b1-446a-4e88-9e40-9fe76d= 2c442d, port=3D5901}<br />2018-02-12 16:46:46,268+01 INFO [org.ov= irt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (DefaultQuart= zScheduler5) [7fcb200a] Received a lease Device without an address when= processing VM 3f57e669-5e4c-4d10-85cc-d573004a099d devices, skipping d= evice: {lease=5Fid=3D3f57e669-5e4c-4d10-85cc-d573004a099d, sd=5Fid=3D1e= 51cecc-eb2e-47d0-b185-920fdc7afa16, deviceId=3D{uuid=3Da09949aa-5642-4b= 6d-94a4-8b0d04257be5}, offset=3D6291456, device=3Dlease, path=3D/rhev/d= ata-center/mnt/glusterSD/192.168.0.6:=5FDATA01/1e51cecc-eb2e-47d0-b185-= 920fdc7afa16/dom=5Fmd/xleases, type=3Dlease}<p> </p></blockquote><= br />For the VM with 2 vdisks we see :<blockquote><p>2018-02-12 16:49:0= 6,112+01 INFO [org.ovirt.engine.core.bll.MigrateVmToServerCommand= ] (default task-50) [92b5af33-cb87-4142-b8fe-8b838dd7458e] Lock Acquire= d to object 'EngineLock:{exclusiveLocks=3D'[f7d4ec12-627a-4b83-b59e-886= 400d55474=3DVM]', sharedLocks=3D''}'<br />2018-02-12 16:49:06,407+01 IN= FO [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (org.ovir= t.thread.pool-6-thread-49) [92b5af33-cb87-4142-b8fe-8b838dd7458e] Runni= ng command: MigrateVmToServerCommand internal: false. Entities affected= : ID: f7d4ec12-627a-4b83-b59e-886400d55474 Type: VMAction group = MIGRATE=5FVM with role type USER<br />2018-02-12 16:49:06,712+01 INFO &= nbsp;[org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (org.ovirt.thr= ead.pool-6-thread-49) [92b5af33-cb87-4142-b8fe-8b838dd7458e] START, Mig= rateVDSCommand( MigrateVDSCommandParameters:{runAsync=3D'true', hostId=3D= 'd569c2dd-8f30-4878-8aea-858db285cf69', vmId=3D'f7d4ec12-627a-4b83-b59e= -886400d55474', srcHost=3D'192.168.0.5', dstVdsId=3D'ce3938b1-b23f-4d22= -840a-f17d7cd87bb1', dstHost=3D'192.168.0.6:54321', migrationMethod=3D'= ONLINE', tunnelMigration=3D'false', migrationDowntime=3D'0', autoConver= ge=3D'true', migrateCompressed=3D'false', consoleAddress=3D'null', maxB= andwidth=3D'500', enableGuestEvents=3D'true', maxIncomingMigrations=3D'= 2', maxOutgoingMigrations=3D'2', convergenceSchedule=3D'[init=3D[{name=3D= setDowntime, params=3D[100]}], stalling=3D[{limit=3D1, action=3D{name=3D= setDowntime, params=3D[150]}}, {limit=3D2, action=3D{name=3DsetDowntime= , params=3D[200]}}, {limit=3D3, action=3D{name=3DsetDowntime, params=3D= [300]}}, {limit=3D4, action=3D{name=3DsetDowntime, params=3D[400]}}, {l= imit=3D6, action=3D{name=3DsetDowntime, params=3D[500]}}, {limit=3D-1, = action=3D{name=3Dabort, params=3D[]}}]]'}), log id: 3702a9e0<br />2018-= 02-12 16:49:06,713+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbr= oker.MigrateBrokerVDSCommand] (org.ovirt.thread.pool-6-thread-49) [92b5= af33-cb87-4142-b8fe-8b838dd7458e] START, MigrateBrokerVDSCommand(HostNa= me =3D ginger.local.systea.fr, MigrateVDSCommandParameters:{runAsync=3D= 'true', hostId=3D'd569c2dd-8f30-4878-8aea-858db285cf69', vmId=3D'f7d4ec= 12-627a-4b83-b59e-886400d55474', srcHost=3D'192.168.0.5', dstVdsId=3D'c= e3938b1-b23f-4d22-840a-f17d7cd87bb1', dstHost=3D'192.168.0.6:54321', mi= grationMethod=3D'ONLINE', tunnelMigration=3D'false', migrationDowntime=3D= '0', autoConverge=3D'true', migrateCompressed=3D'false', consoleAddress= =3D'null', maxBandwidth=3D'500', enableGuestEvents=3D'true', maxIncomin= gMigrations=3D'2', maxOutgoingMigrations=3D'2', convergenceSchedule=3D'= [init=3D[{name=3DsetDowntime, params=3D[100]}], stalling=3D[{limit=3D1,= action=3D{name=3DsetDowntime, params=3D[150]}}, {limit=3D2, action=3D{= name=3DsetDowntime, params=3D[200]}}, {limit=3D3, action=3D{name=3DsetD= owntime, params=3D[300]}}, {limit=3D4, action=3D{name=3DsetDowntime, pa= rams=3D[400]}}, {limit=3D6, action=3D{name=3DsetDowntime, params=3D[500= ]}}, {limit=3D-1, action=3D{name=3Dabort, params=3D[]}}]]'}), log id: 1= 840069c<br />2018-02-12 16:49:06,724+01 INFO [org.ovirt.engine.co= re.vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (org.ovirt.thread.pool-= 6-thread-49) [92b5af33-cb87-4142-b8fe-8b838dd7458e] FINISH, MigrateBrok= erVDSCommand, log id: 1840069c<br />2018-02-12 16:49:06,732+01 INFO &nb= sp;[org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (org.ovirt.threa= d.pool-6-thread-49) [92b5af33-cb87-4142-b8fe-8b838dd7458e] FINISH, Migr= ateVDSCommand, return: MigratingFrom, log id: 3702a9e0<br />2018-02-12 = 16:49:06,753+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditlog= handling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-49) [92b5af3= 3-cb87-4142-b8fe-8b838dd7458e] EVENT=5FID: VM=5FMIGRATION=5FSTART(62), = Correlation ID: 92b5af33-cb87-4142-b8fe-8b838dd7458e, Job ID: f4f54054-= f7c8-4481-8eda-d5a15c383061, Call Stack: null, Custom ID: null, Custom = Event ID: -1, Message: Migration started (VM: Oracle=5FPRIMARY, Source:= ginger.local.systea.fr, Destination: victor.local.systea.fr, User: adm= in@internal-authz).<br />...<br />2018-02-12 16:49:16,453+01 INFO = ;[org.ovirt.engine.core.vdsbroker.monitoring.VmsStatisticsFetcher] (Def= aultQuartzScheduler4) [162a5bc3] Fetched 2 VMs from VDS 'ce3938b1-b23f-= 4d22-840a-f17d7cd87bb1'<br />2018-02-12 16:49:16,455+01 INFO [org= .ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (DefaultQuartzSched= uler4) [162a5bc3] VM 'f7d4ec12-627a-4b83-b59e-886400d55474'(Oracle=5FPR= IMARY) was unexpectedly detected as 'MigratingTo' on VDS 'ce3938b1-b23f= -4d22-840a-f17d7cd87bb1'(victor.local.systea.fr) (expected on 'd569c2dd= -8f30-4878-8aea-858db285cf69')<br />2018-02-12 16:49:16,455+01 INFO &nb= sp;[org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (DefaultQuar= tzScheduler4) [162a5bc3] VM 'f7d4ec12-627a-4b83-b59e-886400d55474' is m= igrating to VDS 'ce3938b1-b23f-4d22-840a-f17d7cd87bb1'(victor.local.sys= tea.fr) ignoring it in the refresh until migration is done<br />...<br = />2018-02-12 16:49:31,484+01 INFO [org.ovirt.engine.core.vdsbroke= r.monitoring.VmAnalyzer] (DefaultQuartzScheduler5) [11a7619a] VM 'f7d4e= c12-627a-4b83-b59e-886400d55474'(Oracle=5FPRIMARY) was unexpectedly det= ected as 'MigratingTo' on VDS 'ce3938b1-b23f-4d22-840a-f17d7cd87bb1'(vi= ctor.local.systea.fr) (expected on 'd569c2dd-8f30-4878-8aea-858db285cf6= 9')<br />2018-02-12 16:49:31,484+01 INFO [org.ovirt.engine.core.v= dsbroker.monitoring.VmAnalyzer] (DefaultQuartzScheduler5) [11a7619a] VM= 'f7d4ec12-627a-4b83-b59e-886400d55474' is migrating to VDS 'ce3938b1-b= 23f-4d22-840a-f17d7cd87bb1'(victor.local.systea.fr) ignoring it in the = refresh until migration is done<br /> </p></blockquote><br />and s= o on, last lines repeated indefinitly for hours since we poweroff the V= M...<br />Is this something known ? Any idea about that ?<br /><br />Th= anks<br />--<br /><style type=3D"text/css">.Text1 { color: black; font-size:9pt; font-family:Verdana; } .Text2 { color: black; font-size:7pt; font-family:Verdana; }</style><p class=3D"Text1">Cordialement,<br /><br /><b>Frank Soyer= </b><br /> </p></html> ------=_=-_OpenGroupware_org_NGMime-15477-1518516470.384163-4--------
Hi Frank, Can you please attach the VDSM logs from the time of the migration failure for both hosts: ginger.local.systea.f <http://ginger.local.systea.fr/>r and v ictor.local.systea.fr Thanks, Maor On Tue, Feb 13, 2018 at 12:07 PM, fsoyer <fsoyer@systea.fr> wrote:
Hi all, I discovered yesterday a problem when migrating VM with more than one vdisk. On our test servers (oVirt4.1, shared storage with Gluster), I created 2 VMs needed for a test, from a template with a 20G vdisk. On this VMs I added a 100G vdisk (for this tests I didn't want to waste time to extend the existing vdisks... But I lost time finally...). The VMs with the 2 vdisks works well. Now I saw some updates waiting on the host. I tried to put it in maintenance... But it stopped on the two VM. They were marked "migrating", but no more accessible. Other (small) VMs with only 1 vdisk was migrated without problem at the same time. I saw that a kvm process for the (big) VMs was launched on the source AND destination host, but after tens of minutes, the migration and the VMs was always freezed. I tried to cancel the migration for the VMs : failed. The only way to stop it was to poweroff the VMs : the kvm process died on the 2 hosts and the GUI alerted on a failed migration. In doubt, I tried to delete the second vdisk on one of this VMs : it migrates then without error ! And no access problem. I tried to extend the first vdisk of the second VM, the delete the second vdisk : it migrates now without problem !
So after another test with a VM with 2 vdisks, I can say that this blocked the migration process :(
In engine.log, for a VMs with 1 vdisk migrating well, we see :
2018-02-12 16:46:29,705+01 INFO [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (default task-28) [2f712024-5982-46a8-82c8-fd8293da5725] Lock Acquired to object 'EngineLock:{exclusiveLocks='[3f57e669-5e4c-4d10-85cc-d573004a099d=VM]', sharedLocks=''}' 2018-02-12 16:46:29,955+01 INFO [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (org.ovirt.thread.pool-6-thread-32) [2f712024-5982-46a8-82c8-fd8293da5725] Running command: MigrateVmToServerCommand internal: false. Entities affected : ID: 3f57e669-5e4c-4d10-85cc-d573004a099d Type: VMAction group MIGRATE_VM with role type USER 2018-02-12 16:46:30,261+01 INFO [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (org.ovirt.thread.pool-6-thread-32) [2f712024-5982-46a8-82c8-fd8293da5725] START, MigrateVDSCommand( MigrateVDSCommandParameters:{runAsync='true', hostId='ce3938b1-b23f-4d22-840a-f17d7cd87bb1', vmId='3f57e669-5e4c-4d10-85cc-d573004a099d', srcHost='192.168.0.6', dstVdsId='d569c2dd-8f30-4878-8aea-858db285cf69', dstHost=' 192.168.0.5:54321', migrationMethod='ONLINE', tunnelMigration='false', migrationDowntime='0', autoConverge='true', migrateCompressed='false', consoleAddress='null', maxBandwidth='500', enableGuestEvents='true', maxIncomingMigrations='2', maxOutgoingMigrations='2', convergenceSchedule='[init=[{name=setDowntime, params=[100]}], stalling=[{limit=1, action={name=setDowntime, params=[150]}}, {limit=2, action={name=setDowntime, params=[200]}}, {limit=3, action={name=setDowntime, params=[300]}}, {limit=4, action={name=setDowntime, params=[400]}}, {limit=6, action={name=setDowntime, params=[500]}}, {limit=-1, action={name=abort, params=[]}}]]'}), log id: 14f61ee0 2018-02-12 16:46:30,262+01 INFO [org.ovirt.engine.core. vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (org.ovirt.thread.pool-6-thread-32) [2f712024-5982-46a8-82c8-fd8293da5725] START, MigrateBrokerVDSCommand(HostName = victor.local.systea.fr, MigrateVDSCommandParameters:{runAsync='true', hostId='ce3938b1-b23f-4d22-840a-f17d7cd87bb1', vmId='3f57e669-5e4c-4d10-85cc-d573004a099d', srcHost='192.168.0.6', dstVdsId='d569c2dd-8f30-4878-8aea-858db285cf69', dstHost=' 192.168.0.5:54321', migrationMethod='ONLINE', tunnelMigration='false', migrationDowntime='0', autoConverge='true', migrateCompressed='false', consoleAddress='null', maxBandwidth='500', enableGuestEvents='true', maxIncomingMigrations='2', maxOutgoingMigrations='2', convergenceSchedule='[init=[{name=setDowntime, params=[100]}], stalling=[{limit=1, action={name=setDowntime, params=[150]}}, {limit=2, action={name=setDowntime, params=[200]}}, {limit=3, action={name=setDowntime, params=[300]}}, {limit=4, action={name=setDowntime, params=[400]}}, {limit=6, action={name=setDowntime, params=[500]}}, {limit=-1, action={name=abort, params=[]}}]]'}), log id: 775cd381 2018-02-12 16:46:30,277+01 INFO [org.ovirt.engine.core. vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (org.ovirt.thread.pool-6-thread-32) [2f712024-5982-46a8-82c8-fd8293da5725] FINISH, MigrateBrokerVDSCommand, log id: 775cd381 2018-02-12 16:46:30,285+01 INFO [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (org.ovirt.thread.pool-6-thread-32) [2f712024-5982-46a8-82c8-fd8293da5725] FINISH, MigrateVDSCommand, return: MigratingFrom, log id: 14f61ee0 2018-02-12 16:46:30,301+01 INFO [org.ovirt.engine.core.dal. dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-32) [2f712024-5982-46a8-82c8-fd8293da5725] EVENT_ID: VM_MIGRATION_START(62), Correlation ID: 2f712024-5982-46a8-82c8-fd8293da5725, Job ID: 4bd19aa9-cc99-4d02-884e-5a1e857a7738, Call Stack: null, Custom ID: null, Custom Event ID: -1, Message: Migration started (VM: Oracle_SECONDARY, Source: victor.local.systea.fr, Destination: ginger.local.systea.fr, User: admin@internal-authz). 2018-02-12 16:46:31,106+01 INFO [org.ovirt.engine.core. vdsbroker.vdsbroker.FullListVDSCommand] (DefaultQuartzScheduler9) [54a65b66] START, FullListVDSCommand(HostName = victor.local.systea.fr, FullListVDSCommandParameters:{runAsync='true', hostId='ce3938b1-b23f-4d22-840a-f17d7cd87bb1', vmIds='[3f57e669-5e4c-4d10-85cc-d573004a099d]'}), log id: 54b4b435 2018-02-12 16:46:31,147+01 INFO [org.ovirt.engine.core. vdsbroker.vdsbroker.FullListVDSCommand] (DefaultQuartzScheduler9) [54a65b66] FINISH, FullListVDSCommand, return: [{acpiEnable=true, emulatedMachine=pc-i440fx-rhel7.3.0, tabletEnable=true, pid=1493, guestDiskMapping={0QEMU_QEMU_HARDDISK_d890fa68-fba4-4f49-9={name=/dev/sda}, QEMU_DVD-ROM_QM00003={name=/dev/sr0}}, transparentHugePages=true, timeOffset=0, cpuType=Nehalem, smp=2, pauseCode=NOERR, guestNumaNodes=[Ljava.lang.Object;@1d9042cd, smartcardEnable=false, custom={device_fbddd528-7d93-49c6-a286-180e021cb274device_ 879c93ab-4df1-435c-af02-565039fcc254=VmDevice:{id='VmDeviceId:{deviceId=' 879c93ab-4df1-435c-af02-565039fcc254', vmId='3f57e669-5e4c-4d10-85cc-d573004a099d'}', device='unix', type='CHANNEL', bootOrder='0', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=1}', managed='false', plugged='true', readOnly='false', deviceAlias='channel0', customProperties='[]', snapshotId='null', logicalName='null', hostDevice='null'}, device_fbddd528-7d93-49c6-a286-180e021cb274device_ 879c93ab-4df1-435c-af02-565039fcc254device_8945f61a-abbe-4156-8485- a4aa6f1908dbdevice_017b5e59-01c4-4aac-bf0c-b5d9557284d6= VmDevice:{id='VmDeviceId:{deviceId='017b5e59-01c4-4aac-bf0c-b5d9557284d6', vmId='3f57e669-5e4c-4d10-85cc-d573004a099d'}', device='tablet', type='UNKNOWN', bootOrder='0', specParams='[]', address='{bus=0, type=usb, port=1}', managed='false', plugged='true', readOnly='false', deviceAlias='input0', customProperties='[]', snapshotId='null', logicalName='null', hostDevice='null'}, device_fbddd528-7d93-49c6- a286-180e021cb274=VmDevice:{id='VmDeviceId:{deviceId=' fbddd528-7d93-49c6-a286-180e021cb274', vmId='3f57e669-5e4c-4d10-85cc-d573004a099d'}', device='ide', type='CONTROLLER', bootOrder='0', specParams='[]', address='{slot=0x01, bus=0x00, domain=0x0000, type=pci, function=0x1}', managed='false', plugged='true', readOnly='false', deviceAlias='ide', customProperties='[]', snapshotId='null', logicalName='null', hostDevice='null'}, device_fbddd528-7d93-49c6-a286-180e021cb274device_ 879c93ab-4df1-435c-af02-565039fcc254device_8945f61a- abbe-4156-8485-a4aa6f1908db=VmDevice:{id='VmDeviceId:{ deviceId='8945f61a-abbe-4156-8485-a4aa6f1908db', vmId='3f57e669-5e4c-4d10-85cc-d573004a099d'}', device='unix', type='CHANNEL', bootOrder='0', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=2}', managed='false', plugged='true', readOnly='false', deviceAlias='channel1', customProperties='[]', snapshotId='null', logicalName='null', hostDevice='null'}}, vmType=kvm, memSize=8192, smpCoresPerSocket=1, vmName=Oracle_SECONDARY, nice=0, status=Migration Source, maxMemSize=32768, bootMenuEnable=false, vmId=3f57e669-5e4c-4d10-85cc-d573004a099d, numOfIoThreads=2, smpThreadsPerCore=1, memGuaranteedSize=8192, kvmEnable=true, pitReinjection=false, displayNetwork=ovirtmgmt, devices=[Ljava.lang.Object;@28ae66d7, display=vnc, maxVCpus=16, clientIp=, statusTime=4299484520, maxMemSlots=16}], log id: 54b4b435 2018-02-12 16:46:31,150+01 INFO [org.ovirt.engine.core. vdsbroker.monitoring.VmsStatisticsFetcher] (DefaultQuartzScheduler1) [27fac647] Fetched 3 VMs from VDS 'd569c2dd-8f30-4878-8aea-858db285cf69' 2018-02-12 16:46:31,151+01 INFO [org.ovirt.engine.core. vdsbroker.monitoring.VmDevicesMonitoring] (DefaultQuartzScheduler9) [54a65b66] Received a vnc Device without an address when processing VM 3f57e669-5e4c-4d10-85cc-d573004a099d devices, skipping device: {device=vnc, specParams={displayNetwork=ovirtmgmt, keyMap=fr, displayIp=192.168.0.6}, type=graphics, deviceId=813957b1-446a-4e88-9e40-9fe76d2c442d, port=5901} 2018-02-12 16:46:31,151+01 INFO [org.ovirt.engine.core. vdsbroker.monitoring.VmDevicesMonitoring] (DefaultQuartzScheduler9) [54a65b66] Received a lease Device without an address when processing VM 3f57e669-5e4c-4d10-85cc-d573004a099d devices, skipping device: {lease_id=3f57e669-5e4c-4d10-85cc-d573004a099d, sd_id=1e51cecc-eb2e-47d0-b185-920fdc7afa16, deviceId={uuid=a09949aa-5642-4b6d-94a4-8b0d04257be5}, offset=6291456, device=lease, path=/rhev/data-center/mnt/ glusterSD/192.168.0.6:_DATA01/1e51cecc-eb2e-47d0-b185-920fdc7afa16/dom_md/xleases, type=lease} 2018-02-12 16:46:31,152+01 INFO [org.ovirt.engine.core. vdsbroker.monitoring.VmAnalyzer] (DefaultQuartzScheduler1) [27fac647] VM '3f57e669-5e4c-4d10-85cc-d573004a099d'(Oracle_SECONDARY) was unexpectedly detected as 'MigratingTo' on VDS 'd569c2dd-8f30-4878-8aea-858db285cf69'( ginger.local.systea.fr) (expected on 'ce3938b1-b23f-4d22-840a- f17d7cd87bb1') 2018-02-12 16:46:31,152+01 INFO [org.ovirt.engine.core. vdsbroker.monitoring.VmAnalyzer] (DefaultQuartzScheduler1) [27fac647] VM '3f57e669-5e4c-4d10-85cc-d573004a099d' is migrating to VDS 'd569c2dd-8f30-4878-8aea-858db285cf69'(ginger.local.systea.fr) ignoring it in the refresh until migration is done .... 2018-02-12 16:46:41,631+01 INFO [org.ovirt.engine.core. vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-11) [] VM '3f57e669-5e4c-4d10-85cc-d573004a099d' was reported as Down on VDS 'ce3938b1-b23f-4d22-840a-f17d7cd87bb1'(victor.local.systea.fr) 2018-02-12 16:46:41,632+01 INFO [org.ovirt.engine.core. vdsbroker.vdsbroker.DestroyVDSCommand] (ForkJoinPool-1-worker-11) [] START, DestroyVDSCommand(HostName = victor.local.systea.fr, DestroyVmVDSCommandParameters:{runAsync='true', hostId='ce3938b1-b23f-4d22-840a-f17d7cd87bb1', vmId='3f57e669-5e4c-4d10-85cc-d573004a099d', force='false', secondsToWait='0', gracefully='false', reason='', ignoreNoVm='true'}), log id: 560eca57 2018-02-12 16:46:41,650+01 INFO [org.ovirt.engine.core. vdsbroker.vdsbroker.DestroyVDSCommand] (ForkJoinPool-1-worker-11) [] FINISH, DestroyVDSCommand, log id: 560eca57 2018-02-12 16:46:41,650+01 INFO [org.ovirt.engine.core. vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-11) [] VM '3f57e669-5e4c-4d10-85cc-d573004a099d'(Oracle_SECONDARY) moved from 'MigratingFrom' --> 'Down' 2018-02-12 16:46:41,651+01 INFO [org.ovirt.engine.core. vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-11) [] Handing over VM '3f57e669-5e4c-4d10-85cc-d573004a099d'(Oracle_SECONDARY) to Host 'd569c2dd-8f30-4878-8aea-858db285cf69'. Setting VM to status 'MigratingTo' 2018-02-12 16:46:42,163+01 INFO [org.ovirt.engine.core. vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-4) [] VM '3f57e669-5e4c-4d10-85cc-d573004a099d'(Oracle_SECONDARY) moved from 'MigratingTo' --> 'Up' 2018-02-12 16:46:42,169+01 INFO [org.ovirt.engine.core. vdsbroker.vdsbroker.MigrateStatusVDSCommand] (ForkJoinPool-1-worker-4) [] START, MigrateStatusVDSCommand(HostName = ginger.local.systea.fr, MigrateStatusVDSCommandParameters:{runAsync='true', hostId='d569c2dd-8f30-4878-8aea-858db285cf69', vmId='3f57e669-5e4c-4d10-85cc-d573004a099d'}), log id: 7a25c281 2018-02-12 16:46:42,174+01 INFO [org.ovirt.engine.core. vdsbroker.vdsbroker.MigrateStatusVDSCommand] (ForkJoinPool-1-worker-4) [] FINISH, MigrateStatusVDSCommand, log id: 7a25c281 2018-02-12 16:46:42,194+01 INFO [org.ovirt.engine.core.dal. dbbroker.auditloghandling.AuditLogDirector] (ForkJoinPool-1-worker-4) [] EVENT_ID: VM_MIGRATION_DONE(63), Correlation ID: 2f712024-5982-46a8-82c8-fd8293da5725, Job ID: 4bd19aa9-cc99-4d02-884e-5a1e857a7738, Call Stack: null, Custom ID: null, Custom Event ID: -1, Message: Migration completed (VM: Oracle_SECONDARY, Source: victor.local.systea.fr, Destination: ginger.local.systea.fr, Duration: 11 seconds, Total: 11 seconds, Actual downtime: (N/A)) 2018-02-12 16:46:42,201+01 INFO [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (ForkJoinPool-1-worker-4) [] Lock freed to object 'EngineLock:{exclusiveLocks='[3f57e669-5e4c-4d10-85cc-d573004a099d=VM]', sharedLocks=''}' 2018-02-12 16:46:42,203+01 INFO [org.ovirt.engine.core. vdsbroker.vdsbroker.FullListVDSCommand] (ForkJoinPool-1-worker-4) [] START, FullListVDSCommand(HostName = ginger.local.systea.fr, FullListVDSCommandParameters:{runAsync='true', hostId='d569c2dd-8f30-4878-8aea-858db285cf69', vmIds='[3f57e669-5e4c-4d10-85cc-d573004a099d]'}), log id: 7cc65298 2018-02-12 16:46:42,254+01 INFO [org.ovirt.engine.core. vdsbroker.vdsbroker.FullListVDSCommand] (ForkJoinPool-1-worker-4) [] FINISH, FullListVDSCommand, return: [{acpiEnable=true, emulatedMachine=pc-i440fx-rhel7.3.0, afterMigrationStatus=, tabletEnable=true, pid=18748, guestDiskMapping={}, transparentHugePages=true, timeOffset=0, cpuType=Nehalem, smp=2, guestNumaNodes=[Ljava.lang.Object;@760085fd, custom={device_fbddd528-7d93- 49c6-a286-180e021cb274device_879c93ab-4df1-435c-af02- 565039fcc254=VmDevice:{id='VmDeviceId:{deviceId='879c93ab-4df1-435c-af02-565039fcc254', vmId='3f57e669-5e4c-4d10-85cc-d573004a099d'}', device='unix', type='CHANNEL', bootOrder='0', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=1}', managed='false', plugged='true', readOnly='false', deviceAlias='channel0', customProperties='[]', snapshotId='null', logicalName='null', hostDevice='null'}, device_fbddd528-7d93-49c6-a286-180e021cb274device_ 879c93ab-4df1-435c-af02-565039fcc254device_8945f61a-abbe-4156-8485- a4aa6f1908dbdevice_017b5e59-01c4-4aac-bf0c-b5d9557284d6= VmDevice:{id='VmDeviceId:{deviceId='017b5e59-01c4-4aac-bf0c-b5d9557284d6', vmId='3f57e669-5e4c-4d10-85cc-d573004a099d'}', device='tablet', type='UNKNOWN', bootOrder='0', specParams='[]', address='{bus=0, type=usb, port=1}', managed='false', plugged='true', readOnly='false', deviceAlias='input0', customProperties='[]', snapshotId='null', logicalName='null', hostDevice='null'}, device_fbddd528-7d93-49c6- a286-180e021cb274=VmDevice:{id='VmDeviceId:{deviceId=' fbddd528-7d93-49c6-a286-180e021cb274', vmId='3f57e669-5e4c-4d10-85cc-d573004a099d'}', device='ide', type='CONTROLLER', bootOrder='0', specParams='[]', address='{slot=0x01, bus=0x00, domain=0x0000, type=pci, function=0x1}', managed='false', plugged='true', readOnly='false', deviceAlias='ide', customProperties='[]', snapshotId='null', logicalName='null', hostDevice='null'}, device_fbddd528-7d93-49c6-a286-180e021cb274device_ 879c93ab-4df1-435c-af02-565039fcc254device_8945f61a- abbe-4156-8485-a4aa6f1908db=VmDevice:{id='VmDeviceId:{ deviceId='8945f61a-abbe-4156-8485-a4aa6f1908db', vmId='3f57e669-5e4c-4d10-85cc-d573004a099d'}', device='unix', type='CHANNEL', bootOrder='0', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=2}', managed='false', plugged='true', readOnly='false', deviceAlias='channel1', customProperties='[]', snapshotId='null', logicalName='null', hostDevice='null'}}, vmType=kvm, memSize=8192, smpCoresPerSocket=1, vmName=Oracle_SECONDARY, nice=0, status=Up, maxMemSize=32768, bootMenuEnable=false, vmId=3f57e669-5e4c-4d10-85cc-d573004a099d, numOfIoThreads=2, smpThreadsPerCore=1, smartcardEnable=false, maxMemSlots=16, kvmEnable=true, pitReinjection=false, displayNetwork=ovirtmgmt, devices=[Ljava.lang.Object;@2e4d3dd3, memGuaranteedSize=8192, maxVCpus=16, clientIp=, statusTime=4304259600 <(430)%20425-9600>, display=vnc}], log id: 7cc65298 2018-02-12 16:46:42,257+01 INFO [org.ovirt.engine.core. vdsbroker.monitoring.VmDevicesMonitoring] (ForkJoinPool-1-worker-4) [] Received a vnc Device without an address when processing VM 3f57e669-5e4c-4d10-85cc-d573004a099d devices, skipping device: {device=vnc, specParams={displayNetwork=ovirtmgmt, keyMap=fr, displayIp=192.168.0.5}, type=graphics, deviceId=813957b1-446a-4e88-9e40-9fe76d2c442d, port=5901} 2018-02-12 16:46:42,257+01 INFO [org.ovirt.engine.core. vdsbroker.monitoring.VmDevicesMonitoring] (ForkJoinPool-1-worker-4) [] Received a lease Device without an address when processing VM 3f57e669-5e4c-4d10-85cc-d573004a099d devices, skipping device: {lease_id=3f57e669-5e4c-4d10-85cc-d573004a099d, sd_id=1e51cecc-eb2e-47d0-b185-920fdc7afa16, deviceId={uuid=a09949aa-5642-4b6d-94a4-8b0d04257be5}, offset=6291456, device=lease, path=/rhev/data-center/mnt/ glusterSD/192.168.0.6:_DATA01/1e51cecc-eb2e-47d0-b185-920fdc7afa16/dom_md/xleases, type=lease} 2018-02-12 16:46:46,260+01 INFO [org.ovirt.engine.core. vdsbroker.vdsbroker.FullListVDSCommand] (DefaultQuartzScheduler5) [7fcb200a] FINISH, FullListVDSCommand, return: [{acpiEnable=true, emulatedMachine=pc-i440fx-rhel7.3.0, afterMigrationStatus=, tabletEnable=true, pid=18748, guestDiskMapping={0QEMU_QEMU_ HARDDISK_d890fa68-fba4-4f49-9={name=/dev/sda}, QEMU_DVD-ROM_QM00003={name=/dev/sr0}}, transparentHugePages=true, timeOffset=0, cpuType=Nehalem, smp=2, guestNumaNodes=[Ljava.lang. Object;@77951faf, custom={device_fbddd528-7d93- 49c6-a286-180e021cb274device_879c93ab-4df1-435c-af02- 565039fcc254=VmDevice:{id='VmDeviceId:{deviceId='879c93ab-4df1-435c-af02-565039fcc254', vmId='3f57e669-5e4c-4d10-85cc-d573004a099d'}', device='unix', type='CHANNEL', bootOrder='0', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=1}', managed='false', plugged='true', readOnly='false', deviceAlias='channel0', customProperties='[]', snapshotId='null', logicalName='null', hostDevice='null'}, device_fbddd528-7d93-49c6-a286-180e021cb274device_ 879c93ab-4df1-435c-af02-565039fcc254device_8945f61a-abbe-4156-8485- a4aa6f1908dbdevice_017b5e59-01c4-4aac-bf0c-b5d9557284d6= VmDevice:{id='VmDeviceId:{deviceId='017b5e59-01c4-4aac-bf0c-b5d9557284d6', vmId='3f57e669-5e4c-4d10-85cc-d573004a099d'}', device='tablet', type='UNKNOWN', bootOrder='0', specParams='[]', address='{bus=0, type=usb, port=1}', managed='false', plugged='true', readOnly='false', deviceAlias='input0', customProperties='[]', snapshotId='null', logicalName='null', hostDevice='null'}, device_fbddd528-7d93-49c6- a286-180e021cb274=VmDevice:{id='VmDeviceId:{deviceId=' fbddd528-7d93-49c6-a286-180e021cb274', vmId='3f57e669-5e4c-4d10-85cc-d573004a099d'}', device='ide', type='CONTROLLER', bootOrder='0', specParams='[]', address='{slot=0x01, bus=0x00, domain=0x0000, type=pci, function=0x1}', managed='false', plugged='true', readOnly='false', deviceAlias='ide', customProperties='[]', snapshotId='null', logicalName='null', hostDevice='null'}, device_fbddd528-7d93-49c6-a286-180e021cb274device_ 879c93ab-4df1-435c-af02-565039fcc254device_8945f61a- abbe-4156-8485-a4aa6f1908db=VmDevice:{id='VmDeviceId:{ deviceId='8945f61a-abbe-4156-8485-a4aa6f1908db', vmId='3f57e669-5e4c-4d10-85cc-d573004a099d'}', device='unix', type='CHANNEL', bootOrder='0', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=2}', managed='false', plugged='true', readOnly='false', deviceAlias='channel1', customProperties='[]', snapshotId='null', logicalName='null', hostDevice='null'}}, vmType=kvm, memSize=8192, smpCoresPerSocket=1, vmName=Oracle_SECONDARY, nice=0, status=Up, maxMemSize=32768, bootMenuEnable=false, vmId=3f57e669-5e4c-4d10-85cc-d573004a099d, numOfIoThreads=2, smpThreadsPerCore=1, smartcardEnable=false, maxMemSlots=16, kvmEnable=true, pitReinjection=false, displayNetwork=ovirtmgmt, devices=[Ljava.lang.Object;@286410fd, memGuaranteedSize=8192, maxVCpus=16, clientIp=, statusTime=4304263620 <(430)%20426-3620>, display=vnc}], log id: 58cdef4c 2018-02-12 16:46:46,267+01 INFO [org.ovirt.engine.core. vdsbroker.monitoring.VmDevicesMonitoring] (DefaultQuartzScheduler5) [7fcb200a] Received a vnc Device without an address when processing VM 3f57e669-5e4c-4d10-85cc-d573004a099d devices, skipping device: {device=vnc, specParams={displayNetwork=ovirtmgmt, keyMap=fr, displayIp=192.168.0.5}, type=graphics, deviceId=813957b1-446a-4e88-9e40-9fe76d2c442d, port=5901} 2018-02-12 16:46:46,268+01 INFO [org.ovirt.engine.core. vdsbroker.monitoring.VmDevicesMonitoring] (DefaultQuartzScheduler5) [7fcb200a] Received a lease Device without an address when processing VM 3f57e669-5e4c-4d10-85cc-d573004a099d devices, skipping device: {lease_id=3f57e669-5e4c-4d10-85cc-d573004a099d, sd_id=1e51cecc-eb2e-47d0-b185-920fdc7afa16, deviceId={uuid=a09949aa-5642-4b6d-94a4-8b0d04257be5}, offset=6291456, device=lease, path=/rhev/data-center/mnt/ glusterSD/192.168.0.6:_DATA01/1e51cecc-eb2e-47d0-b185-920fdc7afa16/dom_md/xleases, type=lease}
For the VM with 2 vdisks we see :
2018-02-12 16:49:06,112+01 INFO [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (default task-50) [92b5af33-cb87-4142-b8fe-8b838dd7458e] Lock Acquired to object 'EngineLock:{exclusiveLocks='[f7d4ec12-627a-4b83-b59e-886400d55474=VM]', sharedLocks=''}' 2018-02-12 16:49:06,407+01 INFO [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (org.ovirt.thread.pool-6-thread-49) [92b5af33-cb87-4142-b8fe-8b838dd7458e] Running command: MigrateVmToServerCommand internal: false. Entities affected : ID: f7d4ec12-627a-4b83-b59e-886400d55474 Type: VMAction group MIGRATE_VM with role type USER 2018-02-12 16:49:06,712+01 INFO [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (org.ovirt.thread.pool-6-thread-49) [92b5af33-cb87-4142-b8fe-8b838dd7458e] START, MigrateVDSCommand( MigrateVDSCommandParameters:{runAsync='true', hostId='d569c2dd-8f30-4878-8aea-858db285cf69', vmId='f7d4ec12-627a-4b83-b59e-886400d55474', srcHost='192.168.0.5', dstVdsId='ce3938b1-b23f-4d22-840a-f17d7cd87bb1', dstHost=' 192.168.0.6:54321', migrationMethod='ONLINE', tunnelMigration='false', migrationDowntime='0', autoConverge='true', migrateCompressed='false', consoleAddress='null', maxBandwidth='500', enableGuestEvents='true', maxIncomingMigrations='2', maxOutgoingMigrations='2', convergenceSchedule='[init=[{name=setDowntime, params=[100]}], stalling=[{limit=1, action={name=setDowntime, params=[150]}}, {limit=2, action={name=setDowntime, params=[200]}}, {limit=3, action={name=setDowntime, params=[300]}}, {limit=4, action={name=setDowntime, params=[400]}}, {limit=6, action={name=setDowntime, params=[500]}}, {limit=-1, action={name=abort, params=[]}}]]'}), log id: 3702a9e0 2018-02-12 16:49:06,713+01 INFO [org.ovirt.engine.core. vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (org.ovirt.thread.pool-6-thread-49) [92b5af33-cb87-4142-b8fe-8b838dd7458e] START, MigrateBrokerVDSCommand(HostName = ginger.local.systea.fr, MigrateVDSCommandParameters:{runAsync='true', hostId='d569c2dd-8f30-4878-8aea-858db285cf69', vmId='f7d4ec12-627a-4b83-b59e-886400d55474', srcHost='192.168.0.5', dstVdsId='ce3938b1-b23f-4d22-840a-f17d7cd87bb1', dstHost=' 192.168.0.6:54321', migrationMethod='ONLINE', tunnelMigration='false', migrationDowntime='0', autoConverge='true', migrateCompressed='false', consoleAddress='null', maxBandwidth='500', enableGuestEvents='true', maxIncomingMigrations='2', maxOutgoingMigrations='2', convergenceSchedule='[init=[{name=setDowntime, params=[100]}], stalling=[{limit=1, action={name=setDowntime, params=[150]}}, {limit=2, action={name=setDowntime, params=[200]}}, {limit=3, action={name=setDowntime, params=[300]}}, {limit=4, action={name=setDowntime, params=[400]}}, {limit=6, action={name=setDowntime, params=[500]}}, {limit=-1, action={name=abort, params=[]}}]]'}), log id: 1840069c 2018-02-12 16:49:06,724+01 INFO [org.ovirt.engine.core. vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (org.ovirt.thread.pool-6-thread-49) [92b5af33-cb87-4142-b8fe-8b838dd7458e] FINISH, MigrateBrokerVDSCommand, log id: 1840069c 2018-02-12 16:49:06,732+01 INFO [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (org.ovirt.thread.pool-6-thread-49) [92b5af33-cb87-4142-b8fe-8b838dd7458e] FINISH, MigrateVDSCommand, return: MigratingFrom, log id: 3702a9e0 2018-02-12 16:49:06,753+01 INFO [org.ovirt.engine.core.dal. dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-49) [92b5af33-cb87-4142-b8fe-8b838dd7458e] EVENT_ID: VM_MIGRATION_START(62), Correlation ID: 92b5af33-cb87-4142-b8fe-8b838dd7458e, Job ID: f4f54054-f7c8-4481-8eda-d5a15c383061, Call Stack: null, Custom ID: null, Custom Event ID: -1, Message: Migration started (VM: Oracle_PRIMARY, Source: ginger.local.systea.fr, Destination: victor.local.systea.fr, User: admin@internal-authz). ... 2018-02-12 16:49:16,453+01 INFO [org.ovirt.engine.core. vdsbroker.monitoring.VmsStatisticsFetcher] (DefaultQuartzScheduler4) [162a5bc3] Fetched 2 VMs from VDS 'ce3938b1-b23f-4d22-840a-f17d7cd87bb1' 2018-02-12 16:49:16,455+01 INFO [org.ovirt.engine.core. vdsbroker.monitoring.VmAnalyzer] (DefaultQuartzScheduler4) [162a5bc3] VM 'f7d4ec12-627a-4b83-b59e-886400d55474'(Oracle_PRIMARY) was unexpectedly detected as 'MigratingTo' on VDS 'ce3938b1-b23f-4d22-840a-f17d7cd87bb1'( victor.local.systea.fr) (expected on 'd569c2dd-8f30-4878-8aea- 858db285cf69') 2018-02-12 16:49:16,455+01 INFO [org.ovirt.engine.core. vdsbroker.monitoring.VmAnalyzer] (DefaultQuartzScheduler4) [162a5bc3] VM 'f7d4ec12-627a-4b83-b59e-886400d55474' is migrating to VDS 'ce3938b1-b23f-4d22-840a-f17d7cd87bb1'(victor.local.systea.fr) ignoring it in the refresh until migration is done ... 2018-02-12 16:49:31,484+01 INFO [org.ovirt.engine.core. vdsbroker.monitoring.VmAnalyzer] (DefaultQuartzScheduler5) [11a7619a] VM 'f7d4ec12-627a-4b83-b59e-886400d55474'(Oracle_PRIMARY) was unexpectedly detected as 'MigratingTo' on VDS 'ce3938b1-b23f-4d22-840a-f17d7cd87bb1'( victor.local.systea.fr) (expected on 'd569c2dd-8f30-4878-8aea- 858db285cf69') 2018-02-12 16:49:31,484+01 INFO [org.ovirt.engine.core. vdsbroker.monitoring.VmAnalyzer] (DefaultQuartzScheduler5) [11a7619a] VM 'f7d4ec12-627a-4b83-b59e-886400d55474' is migrating to VDS 'ce3938b1-b23f-4d22-840a-f17d7cd87bb1'(victor.local.systea.fr) ignoring it in the refresh until migration is done
and so on, last lines repeated indefinitly for hours since we poweroff the VM... Is this something known ? Any idea about that ?
Thanks --
Cordialement,
*Frank Soyer *
_______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users
participants (2)
-
fsoyer -
Maor Lipchuk