<html><head><meta http-equiv="Content-Type" content="text/html charset=utf-8"></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space;" class=""><br class=""><div><blockquote type="cite" class=""><div class="">On 19 Dec 2017, at 10:14, Arik Hadas <<a href="mailto:ahadas@redhat.com" class="">ahadas@redhat.com</a>> wrote:</div><br class="Apple-interchange-newline"><div class=""><div dir="ltr" class=""><br class=""><div class="gmail_extra"><br class=""><div class="gmail_quote">On Tue, Dec 19, 2017 at 12:20 AM, Michal Skrivanek <span dir="ltr" class=""><<a href="mailto:michal.skrivanek@redhat.com" target="_blank" class="">michal.skrivanek@redhat.com</a>></span> wrote:<br class=""><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-style:solid;border-left-color:rgb(204,204,204);padding-left:1ex"><div class="gmail-HOEnZb"><div class="gmail-h5"><br class="">
> On 18 Dec 2017, at 13:21, Milan Zamazal <<a href="mailto:mzamazal@redhat.com" class="">mzamazal@redhat.com</a>> wrote:<br class="">
><br class="">
> Yedidyah Bar David <<a href="mailto:didi@redhat.com" class="">didi@redhat.com</a>> writes:<br class="">
><br class="">
>> On Mon, Dec 18, 2017 at 10:17 AM, Code Review <<a href="mailto:gerrit@ovirt.org" class="">gerrit@ovirt.org</a>> wrote:<br class="">
>>> Jenkins CI posted comments on this change.<br class="">
>>><br class="">
>><br class="">
>>> View Change<br class="">
>>><br class="">
>>> Patch set 3:Continuous-Integration -1<br class="">
>>><br class="">
>>> Build Failed<br class="">
>>><br class="">
>>> <a href="http://jenkins.ovirt.org/job/ovirt-system-tests_master_check-patch-el7-x86_64/2882/" rel="noreferrer" target="_blank" class="">http://jenkins.ovirt.org/job/<wbr class="">ovirt-system-tests_master_<wbr class="">check-patch-el7-x86_64/2882/</a><br class="">
>>> : FAILURE<br class="">
>><br class="">
>> Console output of above job says:<br class="">
>><br class="">
>> 08:13:34 # migrate_vm:<br class="">
>> 08:16:37 * Collect artifacts:<br class="">
>> 08:16:40 * Collect artifacts: Success (in 0:00:03)<br class="">
>> 08:16:40 # migrate_vm: Success (in 0:03:06)<br class="">
>> 08:16:40 # Results located at<br class="">
>> /dev/shm/ost/deployment-basic-<wbr class="">suite-master/default/006_<wbr class="">migrations.py.junit.xml<br class="">
>> 08:16:40 @ Run test: 006_migrations.py: Success (in 0:03:50)<br class="">
>> 08:16:40 Error occured, aborting<br class="">
>><br class="">
>> The file 006_migrations.py.junit.xml [1] says:<br class="">
>><br class="">
>> <failure type="exceptions.<wbr class="">AssertionError" message="False != True after<br class="">
>> 180 seconds"><br class="">
><br class="">
> Reading the logs, I can see the VM migrates normally and seems to be<br class="">
> reported to Engine correctly. When Engine receives end-of-migration<br class="">
> event, it sends Destroy to the source (which is correct), calls dumpxmls<br class="">
> on the destination in the meantime (looks fine to me) and then calls<br class="">
<br class="">
</div></div>looks like a race between getallvmstats reporting VM as Down (statusTime: 4296271980) being processed, while there is a Down/MigrationSucceeded event arriving (with notify_time 4296273170) at about the same time<br class="">
Unfortunately the vdsm.log is not in DEBUG level so there’s very little information as to why and what exactly did it send out.<br class="">
@infra - can you enable debug log level for vdsm by default? </blockquote><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-style:solid;border-left-color:rgb(204,204,204);padding-left:1ex">
<br class="">
It does look like a race to me - does it reproduce? </blockquote><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-style:solid;border-left-color:rgb(204,204,204);padding-left:1ex">
<div class=""><div class="gmail-h5"><br class="">
> Destroy on the destination, which is weird and I don't understand why<br class="">
> the Destroy is invoked.<br class="">
><br class="">
> Arik, would you like to take a look? Maybe I overlooked something or<br class="">
> maybe there's a bug. The logs are at<br class="">
> <a href="http://jenkins.ovirt.org/job/ovirt-system-tests_master_check-patch-el7-x86_64/2882/artifact/exported-artifacts/basic-suite-master__logs/test_logs/basic-suite-master/post-006_migrations.py/" rel="noreferrer" target="_blank" class="">http://jenkins.ovirt.org/job/<wbr class="">ovirt-system-tests_master_<wbr class="">check-patch-el7-x86_64/2882/<wbr class="">artifact/exported-artifacts/<wbr class="">basic-suite-master__logs/test_<wbr class="">logs/basic-suite-master/post-<wbr class="">006_migrations.py/</a><br class="">
> and the interesting things happen around 2017-12-18 03:13:43,758-05.<br class=""></div></div></blockquote><div class=""><br class=""></div><div class="">So it looks like that:</div><div class="">1. the engine polls the VMs from the source host</div><div class="">2. right after #1 we get the down event with proper exit reason (= migration succeeded) but the engine doesn't process it since the VM is being locked by the monitoring as part of processing that polling (to prevent two analysis of the same VM simultaneously).</div><div class="">3. the result of the polling is a VM in status Down and must probably exit_status=Normal</div><div class="">4. the engine decides to abort the migration and thus the monitoring thread of the source host destroys the VM on the destination host.</div><div class=""><br class=""></div><div class="">Unfortunately we don't have the exit_reason that is returned by the polling.</div><div class="">However, the only option I can think of is that it is different than MigrationSucceeded, because otherwise we would have hand-over the VM to the destination host rather than aborting the migration [1].</div><div class="">That part of the code recently changed as part of [2] - we used to hand-over the VM when we get from the source host:</div><div class="">status = Down + exit_status = Normal </div><div class="">And in the database: previous_status = MigrationFrom</div><div class="">But after that change we require:</div><div class="">status = Down + exit_status = Normal ** + exit_reason = MigrationSucceeded **<br class=""></div><div class="">And in the database: previous_status = MigrationFrom</div><div class=""><br class=""></div><div class="">Long story short, is it possible that VDSM had set the status of the VM to Down and exit_status to Normal but the exit_reason was not updated (yet?) to MigrationSucceeded?</div></div></div></div></div></blockquote><div><br class=""></div>ok, so there might be a plausible explanation</div><div>the guest drive mapping introduced a significant delay into the VM.getStats call since it tries to update the mapping when it detects a change. That is likely to happen on lifecycle changes. In the OST case it took 1.2s to finish the whole call, and in the meantime the migration has finished. The getStats() call is not written with possible state change in mind, so if it so happens and the state moves from anything to Down in the middle of it it returns a Down state without exitCode and exitReason which confuses engine. We started to use the exitReason code to differentiate the various flavors of Down in engine in ~4.1 and in this case it results in misleading “VM powered off by admin” case</div><div><br class=""></div><div>we need to fix the VM.getStats() to handle VM state changes in the middle</div><div>we need to fix the guest drive mapping updates to handle cleanly situations when the VM is either not ready yet or already gone</div><div><br class=""></div><div>Thanks,</div><div>michal</div><div><br class=""></div><div><blockquote type="cite" class=""><div class=""><div dir="ltr" class=""><div class="gmail_extra"><div class="gmail_quote"><div class=""><br class=""></div><div class="">[1] <a href="https://github.com/oVirt/ovirt-engine/blob/master/backend/manager/modules/vdsbroker/src/main/java/org/ovirt/engine/core/vdsbroker/monitoring/VmAnalyzer.java#L291" class="">https://github.com/oVirt/ovirt-engine/blob/master/backend/manager/modules/vdsbroker/src/main/java/org/ovirt/engine/core/vdsbroker/monitoring/VmAnalyzer.java#L291</a></div><div class="">[2] <a href="https://gerrit.ovirt.org/#/c/84387/" class="">https://gerrit.ovirt.org/#/c/84387/</a></div><div class=""> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-style:solid;border-left-color:rgb(204,204,204);padding-left:1ex"><div class=""><div class="gmail-h5">
><br class="">
>> Can someone please have a look? Thanks.<br class="">
>><br class="">
>> As a side note, if indeed this is the cause for the failure for the<br class="">
>> job, it's misleading to say "migrate_vm: Success".<br class="">
>><br class="">
>> [1]<br class="">
>> <a href="http://jenkins.ovirt.org/job/ovirt-system-tests_master_check-patch-el7-x86_64/2882/artifact/exported-artifacts/basic-suite-master__logs/006_migrations.py.junit.xml" rel="noreferrer" target="_blank" class="">http://jenkins.ovirt.org/job/<wbr class="">ovirt-system-tests_master_<wbr class="">check-patch-el7-x86_64/2882/<wbr class="">artifact/exported-artifacts/<wbr class="">basic-suite-master__logs/006_<wbr class="">migrations.py.junit.xml</a><br class="">
>><br class="">
>>><br class="">
>>> To view, visit change 85177. To unsubscribe, visit settings.<br class="">
>>><br class="">
>>> Gerrit-Project: ovirt-system-tests<br class="">
>>> Gerrit-Branch: master<br class="">
>>> Gerrit-MessageType: comment<br class="">
>>> Gerrit-Change-Id: I7eb386744a2a2faf0acd734e0ba44<wbr class="">be22dd590b5<br class="">
>>> Gerrit-Change-Number: 85177<br class="">
>>> Gerrit-PatchSet: 3<br class="">
>>> Gerrit-Owner: Yedidyah Bar David <<a href="mailto:didi@redhat.com" class="">didi@redhat.com</a>><br class="">
>>> Gerrit-Reviewer: Dafna Ron <<a href="mailto:dron@redhat.com" class="">dron@redhat.com</a>><br class="">
>>> Gerrit-Reviewer: Eyal Edri <<a href="mailto:eedri@redhat.com" class="">eedri@redhat.com</a>><br class="">
>>> Gerrit-Reviewer: Jenkins CI<br class="">
>>> Gerrit-Reviewer: Sandro Bonazzola <<a href="mailto:sbonazzo@redhat.com" class="">sbonazzo@redhat.com</a>><br class="">
>>> Gerrit-Reviewer: Yedidyah Bar David <<a href="mailto:didi@redhat.com" class="">didi@redhat.com</a>><br class="">
>>> Gerrit-Comment-Date: Mon, 18 Dec 2017 08:17:11 +0000<br class="">
>>> Gerrit-HasComments: No<br class="">
</div></div>> ______________________________<wbr class="">_________________<br class="">
> Devel mailing list<br class="">
> <a href="mailto:Devel@ovirt.org" class="">Devel@ovirt.org</a><br class="">
> <a href="http://lists.ovirt.org/mailman/listinfo/devel" rel="noreferrer" target="_blank" class="">http://lists.ovirt.org/<wbr class="">mailman/listinfo/devel</a><br class="">
><br class="">
><br class="">
<br class="">
</blockquote></div><br class=""></div></div>
</div></blockquote></div><br class=""></body></html>