| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2018-08-21 | |||
| 15:33:12 | efried | mriedem: Yes, on 024, thanks. | |
| 15:37:58 | mriedem | sean-k-mooney: so we're hitting post-copy and then aborting? | |
| 15:38:19 | mriedem | there are only 2 places that live migration activates the dest host port binding: | |
| 15:38:27 | mriedem | 1. post-copy event callback from libvirt | |
| 15:38:38 | mriedem | 2. _post_live_migration after the hypervisor said the live migration was successful | |
| 15:42:08 | openstackgerrit | Matt Riedemann proposed openstack/nova master: Explicitly fail if trying to attach SR-IOV port https://review.openstack.org/591898 | |
| 15:42:26 | sean-k-mooney | mriedem: http://paste.openstack.org/show/728534/ | |
| 15:42:27 | dansmith | ugh, the expectation that we return an instancelist from get_all makes this harder than I thought | |
| 15:42:53 | sean-k-mooney | i think we are geting an updat form neutron and that is trigering the activate. perhaps hitting the _pos_live_migration code | |
| 15:45:05 | sean-k-mooney | mriedem: lines 43-50 are teh ones im suspicous of | |
| 15:45:43 | mriedem | a neutron event wouldn't make us activate a port | |
| 15:45:47 | mriedem | just refresh the info cache | |
| 15:46:17 | mriedem | Aug 21 16:19:17 devstack2 nova-compute[25894]: WARNING nova.compute.manager [None req-594840ec-7af2-47d2-929b-cef9dda07bb8 service nova] [instance: fead1ca6-beab-4c47-a73e-a3ab7f7c4de2] Received unexpected event network-vif-unplugged-ef02ea3f-9a11-4519-bcd3-2bfca97edf26 for instance with vm_state active and task_state migrating. | |
| 15:46:20 | mriedem | means we ignore it | |
| 15:47:23 | sean-k-mooney | hum ok well on line 50 we activate the port binding for devstack5 which was the destination node. but the migration has already aborted | |
| 15:47:58 | mriedem | Aug 21 16:19:17 devstack2 nova-compute[25894]: DEBUG nova.network.neutronv2.api [None req-c8b07cbc-52f7-4d20-aacc-f3036ad90c8d None None] Activated binding for port ef02ea3f-9a11-4519-bcd3-2bfca97edf26 and host devstack5. {{(pid=25894) activate_port_binding /opt/stack/nova/nova/network/neutronv2/api.py:1352}} | |
| 15:47:58 | mriedem | hmm | |
| 15:48:00 | mriedem | indeed | |
| 15:50:11 | mriedem | sean-k-mooney: do you see any "(Lifecycle Event)" messages right before the traceback on the source node? | |
| 15:50:36 | sean-k-mooney | checking | |
| 15:51:37 | mriedem | should have also seen "Binding ports to destination host" if it was handle_lifecycle_event was what was activating the binding | |
| 15:51:42 | mriedem | er, | |
| 15:51:50 | mriedem | sean-k-mooney: are these the logs before or after my patch from a few hours ago? | |
| 15:53:04 | sean-k-mooney | before. and ya the migration competes... | |
| 15:53:13 | sean-k-mooney | ill paste the log section | |
| 15:53:43 | mriedem | so you're seeing the "Migration completed" lifecycle event | |
| 15:53:46 | mriedem | ? | |
| 15:54:02 | mriedem | maybe that's sent in both failure and success cases | |
| 15:54:22 | sean-k-mooney | http://paste.openstack.org/show/728539/ | |
| 15:54:56 | mriedem | Aug 21 16:19:16 devstack2 nova-compute[25894]: INFO nova.compute.manager [None req-c8b07cbc-52f7-4d20-aacc-f3036ad90c8d None None] [instance: fead1ca6-beab-4c47-a73e-a3ab7f7c4de2] VM Migration completed (Lifecycle Event) | |
| 15:54:56 | mriedem | bingo | |
| 15:55:02 | sean-k-mooney | line 25 is the completion and line 31 is the failue | |
| 15:55:13 | mriedem | Aug 21 16:19:17 devstack2 nova-compute[25894]: DEBUG nova.compute.manager [None req-c8b07cbc-52f7-4d20-aacc-f3036ad90c8d None None] [instance: fead1ca6-beab-4c47-a73e-a3ab7f7c4de2] Binding ports to destination host: devstack5 {{(pid=25894) handle_lifecycle_event /opt/stack/nova/nova/compute/manager.py:1130}} | |
| 15:55:28 | sean-k-mooney | ya i just saw that too | |
| 15:55:30 | mriedem | Aug 21 16:19:17 devstack2 nova-compute[25894]: ERROR nova.virt.libvirt.driver [-] [instance: fead1ca6-beab-4c47-a73e-a3ab7f7c4de2] Live Migration failure: internal error: qemu unexpectedly closed the monitor: 2018-08-21T15:19:15.187710Z qemu-kvm: -chardev socket,id=charnet0,path=/var/run/openvswitch/vhuef02ea3f-9a,server: info: QEMU waiting | |
| 15:55:44 | mriedem | yeah so the driver is sending the 'migration completed' event even though the job failed | |
| 15:55:46 | mriedem | that's the bug | |
| 15:55:52 | mriedem | and that's why we are activating the dest host port bindings on failure | |
| 15:56:03 | mriedem | and then deleting them in rollback :) | |
| 15:56:30 | sean-k-mooney | ya. so libvirt bug? | |
| 15:56:36 | mriedem | libvirt driver bug yeah | |
| 15:57:04 | sean-k-mooney | well the live migration completion event is comming from libvirt no? | |
| 15:57:22 | mriedem | yes, but the driver should check the job status to see if it failed or not | |
| 15:57:23 | mriedem | if we can | |
| 15:57:27 | mriedem | otherwise i don't think we can rely on that event | |
| 15:57:50 | sean-k-mooney | let me see if danpb is about | |
| 15:57:52 | openstackgerrit | Chris Dent proposed openstack/nova master: Set policy_opt defaults in placement deploy unit test https://review.openstack.org/594334 | |
| 15:59:49 | sean-k-mooney | danpb: thanks. am regarding http://paste.openstack.org/show/728539/. does the live migration completion event from libvirt have a status we can check for failures? | |
| 15:59:50 | mriedem | i've updated https://review.openstack.org/#/c/594139/ with comments | |
| 15:59:52 | danpb | sean-k-mooney: you summoned me :-) | |
| 16:00:04 | mriedem | how many goats had to be sacrificed? | |
| 16:00:29 | sean-k-mooney | haha TBD | |
| 16:01:29 | danpb | sean-k-mooney: you have any more context than just that log file ? | |
| 16:01:56 | sean-k-mooney | danpb: yes im testing live migration between ovs to ovs-dpdk in this case | |
| 16:02:07 | sean-k-mooney | that is causing qemu to have an internal error | |
| 16:02:30 | mdbooth | mriedem: I think if we've reached the point of post-copy, we shouldn't rollback. | |
| 16:02:30 | danpb | yep, looks like QEMU on target saw error in expected state & exited | |
| 16:02:40 | sean-k-mooney | nova is assuming that when we get the live migration complete event that everything worked fine bug in this case qemu explodes and the migration failes | |
| 16:02:41 | danpb | whcih should have caused libvirt to abort migration & nova to rollback | |
| 16:02:46 | mdbooth | mriedem: Because the guest was actually running on the destination at that point. | |
| 16:03:19 | mdbooth | Guessing that could be tricky with the current code structure, though... | |
| 16:03:23 | danpb | mdbooth: this logfile isn't showing post-coyp is it ? looks like normal pre-copy to me | |
| 16:03:38 | sean-k-mooney | mdbooth: the guest is still running fine after this. is netwroking is messed up but its still running on the host | |
| 16:03:43 | mriedem | mdbooth: we aren't hitting post-copy | |
| 16:03:44 | mdbooth | danpb: We could be talking about different things. I was referring to https://review.openstack.org/#/c/594139/ | |
| 16:04:11 | danpb | oh fun, two different live migration discussions in parallel :-) | |
| 16:04:22 | sean-k-mooney | mdbooth: danpb its the same one | |
| 16:04:25 | mriedem | danpb: so this is all new code since you've been in nova | |
| 16:04:28 | sean-k-mooney | i reproduced it | |
| 16:04:52 | mriedem | we're just assuming "migration completed" means it was successful, which is wrong in this case | |
| 16:05:11 | mriedem | so just need to not send that event callback up to the compute manager if the job failed | |
| 16:05:19 | mriedem | which i think we can glean from the jobState object | |
| 16:05:35 | mriedem | assuming that info is available to us in the params to _event_lifecycle_callback | |
| 16:06:19 | mriedem | i'm not sure that it does though, we get event and detail | |
| 16:06:22 | mriedem | but not the job status | |
| 16:07:07 | danpb | mriedem: which migration events are you referring to ? | |
| 16:07:45 | mdbooth | I don't think we're actually consuming events. We're polling the migration job. | |
| 16:07:51 | mriedem | https://github.com/openstack/nova/blob/master/nova/virt/libvirt/host.py#L179-L184 | |
| 16:07:59 | mriedem | mdbooth: no | |
| 16:08:03 | mriedem | not for this | |
| 16:08:26 | danpb | oh, so you're just looking at the lifecycle events | |
| 16:08:40 | mdbooth | mriedem: ack. Was looking at _live_migration_monitor. | |
| 16:08:59 | danpb | i'm not convinced that's not a desirable way to determine success vs failure | |
| 16:09:09 | mriedem | we're getting VIR_DOMAIN_EVENT_SUSPENDED_MIGRATED | |
| 16:09:17 | mriedem | and assuming it's success | |
| 16:09:23 | danpb | the the job status from the _live_migration_monitor is better way to check for failure | |
| 16:09:31 | mriedem | yeah, but we're on different threads here | |
| 16:09:43 | mriedem | we have the domain, could we get the jobState from that? | |
| 16:09:54 | danpb | mriedem: that VIR_DOMAIN_EVENT_SUSPENDED_MIGRATED just says that the guest has been paused, as a result of the live migration operation | |
| 16:10:03 | danpb | it doesn't say anything about the operation being success or failure | |
| 16:10:14 | mriedem | right, and that's our bug :) | |
| 16:10:18 | danpb | so you definitely can't assume success from that | |
| 16:11:22 | mriedem | right, | |
| 16:11:26 | mriedem | so i can remove that to fix this quick | |
| 16:11:39 | mriedem | or try to find the jobState from the domain and check the status? | |
| 16:11:42 | dansmith | Kevin_Zheng: okay I've changed my mind for the moment.. the api code is so generator-unfriendly that a quick hack to test this is more involved than I thought | |
| 16:11:59 | danpb | mriedem: if there's some action that needs to take place during the migration operation | |
| 16:12:18 | danpb | mriedem: then my gut feeling would be to hav the _live_migration_monitor thread take care of it | |
| 16:12:26 | sean-k-mooney | mriedem: well im not sure we need to change that code. where is the EVENT_LIFECYCLE_MIGRATION_COMPLETED event consumed because we have stopped moving stuff at this point we jsut dont know if it succeded | |
| 16:12:41 | mriedem | danpb: yeah most likely - and that's inline with what dansmith said on the review for this change | |