Re: [ovirt-devel] [ OST Failure Report ] [ oVirt master ] [ 03-07-2017 ] [ 006_migrations.migrate_vm ]

--Apple-Mail=_F6BEE682-0833-4DDF-AC85-B3A2BC1EDFF6 Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8 http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/7431/ = <http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/7431/> http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/7431/arti= fact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master= /post-006_migrations.py/ = <http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/7431/art= ifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-maste= r/post-006_migrations.py/> VM. There is no host that satisfies current scheduling constraints. See = below for details:, The host lago-basic-suite-master-host0 did not = satisfy internal filter CPUOverloaded because its CPU is too loaded.]" [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (default task-27) = [87508047-fdc5-4a2f-9692-c83f7b55bbc2] Lock Acquired to object = 'EngineLock:{exclusiveLocks=3D'[2b34910d-cef2-44d6-a274-30e8473eb5d9=3DVM]= ', sharedLocks=3D''}' [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimple= JdbcCall] (default task-27) [87508047-fdc5-4a2f-9692-c83f7b55bbc2] = Compiled stored procedure. Call string is [{call = getdiskvmelementspluggedtovm(?)}] [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimple= JdbcCall] (default task-27) [87508047-fdc5-4a2f-9692-c83f7b55bbc2] = SqlCall for procedure [GetDiskVmElementsPluggedToVm] compiled [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimple= JdbcCall] (default task-27) [87508047-fdc5-4a2f-9692-c83f7b55bbc2] = Compiled stored procedure. Call string is [{call = getattacheddisksnapshotstovm(?, ?)}] [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimple= JdbcCall] (default task-27) [87508047-fdc5-4a2f-9692-c83f7b55bbc2] = SqlCall for procedure [GetAttachedDiskSnapshotsToVm] compiled [org.ovirt.engine.core.bll.scheduling.SchedulingManager] (default = task-27) [87508047-fdc5-4a2f-9692-c83f7b55bbc2] Candidate host = 'lago-basic-suite-master-host0' ('46bdc63d-98f5-4eee-81aa-2fb88b8f7cbe') = was filtered out by 'VAR__FILTERTYPE__INTERNAL' filter 'CPUOverloaded' = (correlation id: null) [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (default task-27) = [87508047-fdc5-4a2f-9692-c83f7b55bbc2] Validation of action = 'MigrateVmToServer' failed for user admin@internal-authz. Reasons: = VAR__ACTION__MIGRATE,VAR__TYPE__VM,SCHEDULING_ALL_HOSTS_FILTERED_OUT,VAR__= FILTERTYPE__INTERNAL,$hostName lago-basic-suite-master-host0,$filterName = CPUOverloaded,VAR__DETAIL__CPU_OVERLOADED,SCHEDULING_HOST_FILTERED_REASON_= WITH_DETAIL This has nothing to do with migration The CPUOverload is a scheduling policy, unless there was any change in = that area the obvious explanation would be that the host has a CPU = overload condition. I briefly looked at logs and see ""cpuUser": "83.40", "cpuSys": "16.59", = "cpuIdle": =E2=80=9C0.08=E2=80=9D=E2=80=9D which indeed suggests an = overload, from the same sample I can see it=E2=80=99s vdsm = ("cpuUserVdsmd": =E2=80=9C77.38=E2=80=9D, cpuSysVdsmd": =E2=80=9C18.44" Since similar values are consistently being reported for some time, and = there is a setupNetworks and storage rescan prior to the the failure, = and there is no other indication of anything wrong, I=E2=80=99d just say = the environment or the order of tests or timing has changed, but nothing = wrong with the oVirt code Did any of that changed recently? Does it reproduce locally? Thanks, michal [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (default task-27) = [87508047-fdc5-4a2f-9692-c83f7b55bbc2] Lock freed to object = 'EngineLock:{exclusiveLocks=3D'[2b34910d-cef2-44d6-a274-30e8473eb5d9=3DVM]= ', sharedLocks=3D''}' [org.ovirt.engine.core.utils.timer.FixedDelayJobListener] = (DefaultQuartzScheduler7) [] Rescheduling = DEFAULT.org.ovirt.engine.core.bll.ColdRebootAutoStartVmsRunner.startFailed= AutoStartVms#-9223372036854775733 as there is no unfired trigger. [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default = task-27) [] Operation Failed: [Cannot migrate VM. There is no host that = satisfies current scheduling constraints. See below for details:, The = host lago-basic-suite-master-host0 did not satisfy internal filter = CPUOverloaded because its CPU is too loaded.] [org.ovirt.engine.core.utils.timer.FixedDelayJobListener] = (DefaultQuartzScheduler2) [] Rescheduling = DEFAULT.org.ovirt.engine.core.bll.HaAutoStartVmsRunner.startFailedAutoStar= tVms#-9223372036854775793 as there is no unfired trigger. [org.ovirt.engine.core.utils.timer.FixedDelayJobListener] = (DefaultQuartzScheduler2) [] Rescheduling = DEFAULT.org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallb= ackMethods#-9223372036854775783 as there is no unfired trigger. --Apple-Mail=_F6BEE682-0833-4DDF-AC85-B3A2BC1EDFF6 Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8 <html><head><meta http-equiv=3D"Content-Type" content=3D"text/html = charset=3Dutf-8"></head><body style=3D"word-wrap: break-word; = -webkit-nbsp-mode: space; -webkit-line-break: after-white-space;" = class=3D""><br class=3D""><div><blockquote type=3D"cite" class=3D""><div = class=3D"">On 3 Jul 2017, at 15:35, Shlomo Ben David &lt;<a = href=3D"mailto:sbendavi@redhat.com" class=3D&quot;&quot;&gt;sbendavi(a)redhat.com&lt;/a&gt;&amp;gt;= wrote:</div><br class=3D"Apple-interchange-newline"><div class=3D""><div = dir=3D"ltr" class=3D"">Hi,<br class=3D""><br class=3D"">Test failed: [ = 006_migrations.migrate_vm ]<br class=3D"">Link to suspected patches: = N/A<br class=3D"">Link to Job: <a = href=3D"http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_ma... 431/" = class=3D"">http://jenkins.ovirt.org/job/test-repo_ovirt_expe... r/7431/</a><br class=3D"">Link to all logs:&nbsp;<br class=3D"">Error = snippet from the log:&nbsp;<a = href=3D"http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_ma... 431/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suit= e-master/post-006_migrations.py/" = class=3D"">http://jenkins.ovirt.org/job/test-repo_ovirt_expe... r/7431/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-s= uite-master/post-006_migrations.py/</a><br class=3D""><br = class=3D"">&lt;error&gt;<br class=3D""><br class=3D"">&nbsp;"Fault = reason is "Operation Failed". Fault detail is "[Cannot migrate VM. There = is no host that satisfies current scheduling constraints. See below for = details:, The host lago-basic-suite-master-host0 did not satisfy = internal filter CPUOverloaded because its CPU is too loaded.]"<div = class=3D""><br class=3D""></div><div class=3D"">&lt;/error&gt;<br = class=3D""></div><div class=3D""><br class=3D""></div><div = class=3D"">&lt;engine log&gt;<br class=3D""></div><div class=3D""><br = class=3D""></div><div class=3D""><div class=3D"">2017-07-02 = 16:43:22,829-04 INFO = &nbsp;[org.ovirt.engine.core.bll.MigrateVmToServerCommand] (default = task-27) [87508047-fdc5-4a2f-9692-c83f7b55bbc2] Lock Acquired to object = 'EngineLock:{exclusiveLocks=3D'[2b34910d-cef2-44d6-a274-30e8473eb5d9=3DVM]= ', sharedLocks=3D''}'</div><div class=3D"">2017-07-02 16:43:22,833-04 = DEBUG = [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimple= JdbcCall] (default task-27) [87508047-fdc5-4a2f-9692-c83f7b55bbc2] = Compiled stored procedure. Call string is [{call = getdiskvmelementspluggedtovm(?)}]</div><div class=3D"">2017-07-02 = 16:43:22,833-04 DEBUG = [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimple= JdbcCall] (default task-27) [87508047-fdc5-4a2f-9692-c83f7b55bbc2] = SqlCall for procedure [GetDiskVmElementsPluggedToVm] compiled</div><div = class=3D"">2017-07-02 16:43:22,843-04 DEBUG = [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimple= JdbcCall] (default task-27) [87508047-fdc5-4a2f-9692-c83f7b55bbc2] = Compiled stored procedure. Call string is [{call = getattacheddisksnapshotstovm(?, ?)}]</div><div class=3D"">2017-07-02 = 16:43:22,843-04 DEBUG = [org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimple= JdbcCall] (default task-27) [87508047-fdc5-4a2f-9692-c83f7b55bbc2] = SqlCall for procedure [GetAttachedDiskSnapshotsToVm] compiled</div><div = class=3D"">2017-07-02 16:43:22,919-04 INFO = &nbsp;[org.ovirt.engine.core.bll.scheduling.SchedulingManager] (default = task-27) [87508047-fdc5-4a2f-9692-c83f7b55bbc2] Candidate host = 'lago-basic-suite-master-host0' ('46bdc63d-98f5-4eee-81aa-2fb88b8f7cbe') = was filtered out by 'VAR__FILTERTYPE__INTERNAL' filter 'CPUOverloaded' = (correlation id: null)</div><div class=3D"">2017-07-02 16:43:22,920-04 = WARN &nbsp;[org.ovirt.engine.core.bll.MigrateVmToServerCommand] (default = task-27) [87508047-fdc5-4a2f-9692-c83f7b55bbc2] Validation of action = 'MigrateVmToServer' failed for user admin@internal-authz. Reasons: = VAR__ACTION__MIGRATE,VAR__TYPE__VM,SCHEDULING_ALL_HOSTS_FILTERED_OUT,VAR__= FILTERTYPE__INTERNAL,$hostName lago-basic-suite-master-host0,$filterName = CPUOverloaded,VAR__DETAIL__CPU_OVERLOADED,SCHEDULING_HOST_FILTERED_REASON_= WITH_DETAIL</div></div></div></div></blockquote><div><br = class=3D""><div><br class=3D""></div><div>This has nothing to do with = migration<br class=3D"">The CPUOverload is a scheduling policy, unless = there was any change in that area the obvious explanation would be that = the host has a CPU overload condition.<br class=3D"">I briefly looked at = logs and see ""cpuUser": "83.40", "cpuSys": "16.59", "cpuIdle": = =E2=80=9C0.08=E2=80=9D=E2=80=9D which indeed suggests an overload, from = the same sample I can see it=E2=80=99s vdsm ("cpuUserVdsmd": = =E2=80=9C77.38=E2=80=9D, cpuSysVdsmd":&nbsp;=E2=80=9C18.44"<br = class=3D""><br class=3D""></div>Since similar values are consistently = being reported for some time, and there is a setupNetworks and storage = rescan prior to the the failure, and there is no other indication of = anything wrong, I=E2=80=99d just say the environment or the order of = tests or timing has changed, but nothing wrong with the oVirt = code</div><div>Did any of that changed recently? Does it reproduce = locally?</div><div><br = class=3D""></div><div>Thanks,</div><div>michal</div><div><br = class=3D""></div><blockquote type=3D"cite" class=3D""><div class=3D""><div= dir=3D"ltr" class=3D""><div class=3D""><div class=3D"">2017-07-02 = 16:43:22,920-04 INFO = &nbsp;[org.ovirt.engine.core.bll.MigrateVmToServerCommand] (default = task-27) [87508047-fdc5-4a2f-9692-c83f7b55bbc2] Lock freed to object = 'EngineLock:{exclusiveLocks=3D'[2b34910d-cef2-44d6-a274-30e8473eb5d9=3DVM]= ', sharedLocks=3D''}'</div><div class=3D"">2017-07-02 16:43:22,929-04 = DEBUG [org.ovirt.engine.core.utils.timer.FixedDelayJobListener] = (DefaultQuartzScheduler7) [] Rescheduling <a href=3D"http://DEFAULT.org" = class=3D"">DEFAULT.org</a>.ovirt.engine.core.bll.ColdRebootAutoStartVmsRun= ner.startFailedAutoStartVms#-9223372036854775733 as there is no unfired = trigger.</div><div class=3D"">2017-07-02 16:43:22,932-04 ERROR = [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default = task-27) [] Operation Failed: [Cannot migrate VM. There is no host that = satisfies current scheduling constraints. See below for details:, The = host lago-basic-suite-master-host0 did not satisfy internal filter = CPUOverloaded because its CPU is too loaded.]</div><div = class=3D"">2017-07-02 16:43:23,331-04 DEBUG = [org.ovirt.engine.core.utils.timer.FixedDelayJobListener] = (DefaultQuartzScheduler2) [] Rescheduling <a href=3D"http://DEFAULT.org" = class=3D"">DEFAULT.org</a>.ovirt.engine.core.bll.HaAutoStartVmsRunner.star= tFailedAutoStartVms#-9223372036854775793 as there is no unfired = trigger.</div><div class=3D"">2017-07-02 16:43:23,332-04 DEBUG = [org.ovirt.engine.core.utils.timer.FixedDelayJobListener] = (DefaultQuartzScheduler2) [] Rescheduling <a href=3D"http://DEFAULT.org" = class=3D"">DEFAULT.org</a>.ovirt.engine.core.bll.tasks.CommandCallbacksPol= ler.invokeCallbackMethods#-9223372036854775783 as there is no unfired = trigger.</div><div class=3D""><br class=3D""></div>&lt;engine log&gt;<br = class=3D""><br class=3D""><div class=3D""><br class=3D""></div><br = clear=3D"all" class=3D""><div class=3D""><div = class=3D"gmail_signature"><div dir=3D"ltr" class=3D""><div class=3D""><div= dir=3D"ltr" class=3D""><div dir=3D"ltr" class=3D""><div dir=3D"ltr" = class=3D""><div dir=3D"ltr" class=3D""><div dir=3D"ltr" class=3D""><div = dir=3D"ltr" class=3D""><div class=3D"">Best Regards,</div><div dir=3D"ltr"= class=3D""><br class=3D""></div><div dir=3D"ltr" class=3D"">Shlomi = Ben-David | Software Engineer <span style=3D"font-size:small" = class=3D"">|&nbsp;</span><span style=3D"font-size:12.8px" class=3D"">Red = Hat ISRAEL</span></div><div class=3D"">RHCSA |&nbsp;<span = style=3D"font-size:small" class=3D"">RHCVA |&nbsp;</span><span = style=3D"font-size:small" class=3D"">RHCE</span></div><div dir=3D"ltr" = class=3D"">IRC: shlomibendavid&nbsp;<span style=3D"font-size:small" = class=3D"">(on #rhev-integ, #rhev-dev, #rhev-ci)</span><br class=3D""><br = class=3D"">OPEN SOURCE - 1 4 011 &amp;&amp; 011 4 1<br class=3D""><br = class=3D""></div></div></div></div></div></div></div></div></div></div></d= iv> </div></div> _______________________________________________<br class=3D"">Devel = mailing list<br class=3D""><a href=3D"mailto:Devel@ovirt.org" = class=3D&quot;&quot;&gt;Devel(a)ovirt.org&lt;/a&gt;&lt;br = class=3D"">http://lists.ovirt.org/mailman/listinfo/devel<... --Apple-Mail=_F6BEE682-0833-4DDF-AC85-B3A2BC1EDFF6--