Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2018-08-21
15:33:01 sean-k-mooney mriedem: so regarding the live migration bug. the source node is activating the binding on the dest host binding after the migration aborts and this is also racing with the deltion of the binding on the dest host ...
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 hmm
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: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 bingo
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: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 danpb yep, looks like QEMU on target saw error in expected state & exited
16:02:30 mdbooth mriedem: I think if we've reached the point of post-copy, we shouldn't rollback.
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

Earlier   Later