| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2018-08-09 | |||
| 19:56:10 | mriedem | 2018-08-09 21:20:20.558 12111 DEBUG nova.compute.manager [req-84ca4a17-0d3d-4597-91d6-f5721989dd41 143ee57edd4d4e3b9a165d375d0e7e1a a727713d2c0a4ed69b730d9cb2116af6 - default default] [instance: c37d7489-a67b-47ea-a4f7-9323804cc552] No waiting events found dispatching network-vif-plugged-490f6f25-8b88-487c-a76b-62d16e3c0da1 pop_instance_event /openstack/venvs/nova-r16.2.2/lib/python2.7/site-packages/nova/compute/manager.py:36 | |
| 19:56:18 | mriedem | 2018-08-09 21:20:20.559 12111 WARNING nova.compute.manager [req-84ca4a17-0d3d-4597-91d6-f5721989dd41 143ee57edd4d4e3b9a165d375d0e7e1a a727713d2c0a4ed69b730d9cb2116af6 - default default] [instance: c37d7489-a67b-47ea-a4f7-9323804cc552] Received unexpected event network-vif-plugged-490f6f25-8b88-487c-a76b-62d16e3c0da1 for instance | |
| 19:56:33 | prometheanfire | this is a pike install btw | |
| 19:56:46 | mriedem | maybe we're getting the event before we're waiting for it? | |
| 19:56:47 | prometheanfire | but it was backported to pike, so meh | |
| 19:56:51 | prometheanfire | perhaps | |
| 19:57:11 | mriedem | we could also be getting ^ from the vif plug that happens on the dest host during pre-live migration | |
| 19:57:19 | mriedem | the events are going to go to the source host | |
| 19:57:22 | mriedem | which isn't waiting for those | |
| 19:57:29 | prometheanfire | not yet at least, ya | |
| 19:57:59 | mriedem | https://github.com/openstack/nova/commit/ff747792b8f5aefe1bebb01bdf49dacc01353348#diff-f4019782d93a196a0d026479e6aa61b1R6899 | |
| 19:58:32 | mriedem | "They are going to be # created by libvirt at the very beginning of the # live-migration process." | |
| 19:58:39 | prometheanfire | yep | |
| 19:58:42 | mriedem | that must mean plug_vifs during pre-live migration on the dest host | |
| 19:58:42 | prometheanfire | I read that :P | |
| 19:58:51 | mriedem | which triggers the event from neutron to the source host | |
| 19:58:58 | mriedem | and we're getting it before we start waiting it looks like | |
| 19:59:00 | prometheanfire | which isn't waiting yet? | |
| 19:59:02 | prometheanfire | ya | |
| 19:59:12 | mriedem | but, you should then hit this https://github.com/openstack/nova/commit/ff747792b8f5aefe1bebb01bdf49dacc01353348#diff-f4019782d93a196a0d026479e6aa61b1R6933 | |
| 19:59:19 | mriedem | and the migration should fail | |
| 19:59:26 | prometheanfire | also yes | |
| 20:00:03 | mriedem | added https://github.com/openstack/nova/blob/master/nova/conf/compute.py#L675 in rocky but that doesn't help you here on pike | |
| 20:01:05 | prometheanfire | yarp | |
| 20:01:16 | mriedem | we can't backport that either b/c it's got rpc changes in it | |
| 20:01:41 | mriedem | so maybe the raised MigrationError isn't really doing anything? | |
| 20:02:05 | mriedem | i expect you to know exactly how all of this nova code works | |
| 20:02:14 | prometheanfire | lolol | |
| 20:02:56 | prometheanfire | ya, I'm honestly surprised that it finished, I expected it to fail | |
| 20:02:57 | mriedem | no it shoud raise up, | |
| 20:03:03 | mriedem | i was thinking we might be threaded but that's here https://github.com/openstack/nova/blob/ff747792b8f5aefe1bebb01bdf49dacc01353348/nova/virt/libvirt/driver.py#L6928 | |
| 20:03:11 | prometheanfire | maybe eventlet.timeout.Timeout isn't the actual error getting raised? | |
| 20:03:29 | openstackgerrit | Merged openstack/nova stable/queens: Update nova network info when doing rebuild for evacuate operation https://review.openstack.org/590062 | |
| 20:04:18 | prometheanfire | maybe we finish the migration before the timeout occurs? | |
| 20:04:34 | mriedem | Timeout is the right error | |
| 20:04:44 | mriedem | prometheanfire: well that's why i asked how long it took, | |
| 20:04:49 | mriedem | but the default timeout is 5 min | |
| 20:04:55 | mriedem | you said it completed in 10 min | |
| 20:05:01 | prometheanfire | went from 21:20 to 21:25 ish | |
| 20:05:16 | mriedem | oh, well that's not 10 min L( | |
| 20:05:17 | mriedem | :) | |
| 20:05:20 | prometheanfire | ya | |
| 20:05:26 | mriedem | so yeah i bet you completed before the timeout | |
| 20:06:25 | mriedem | but honestly, | |
| 20:06:25 | prometheanfire | 21:20:21.043 to 21:27:12.788 at least | |
| 20:06:30 | mriedem | the threading here is messing with my head | |
| 20:06:33 | prometheanfire | Migration running for 410 secs | |
| 20:06:35 | prometheanfire | so over 5 min | |
| 20:06:48 | prometheanfire | yep | |
| 20:06:51 | mriedem | wait_for_instance_event is meant to register events to wait | |
| 20:06:57 | mriedem | then run some code and wait or timeout | |
| 20:07:17 | mriedem | "opthread = utils.spawn(self._live_migration_operation" is what code gets run | |
| 20:08:19 | mriedem | but that should mean we wait until we do "opthread.link(thread_finished, finish_event)" | |
| 20:08:53 | mriedem | even if we get the timeout, it seems this is pretty dangerous if we've already started the live migration in the hypervisor | |
| 20:09:02 | mriedem | i +2ed this code too... | |
| 20:09:12 | prometheanfire | so we can blame you :P | |
| 20:09:15 | mriedem | kinda need dansmith here | |
| 20:09:33 | prometheanfire | ya | |
| 20:09:36 | mriedem | i still don't know why you wouldn't see the timeout message | |
| 20:09:49 | prometheanfire | same | |
| 20:09:59 | mriedem | 2018-08-09 21:27:20.197 12111 DEBUG nova.virt.libvirt.driver [req-84ca4a17-0d3d-4597-91d6-f5721989dd41 143ee57edd4d4e3b9a165d375d0e7e1a a727713d2c0a4ed69b730d9cb2116af6 - default default] [instance: c37d7489-a67b-47ea-a4f7-9323804cc552] Migration operation thread notification thread_finished /openstack/venvs/nova-r16.2.2/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:6952 | |
| 20:09:59 | mriedem | from your log | |
| 20:11:28 | mriedem | sahid will be around in the morning if you can catch him | |
| 20:11:33 | dansmith | catch me up? | |
| 20:11:47 | mriedem | dansmith: prometheanfire is running a linuxbridge live migration in pike, | |
| 20:11:54 | mriedem | with that bw slow down patch of sahid's | |
| 20:12:05 | mriedem | the live migration takes longer than our default vif plugging timeout | |
| 20:12:10 | dansmith | that got backported I assume? | |
| 20:12:25 | mriedem | yeah (from us). and looks like we actually get the event before sahid's code registers to wait, | |
| 20:12:35 | mriedem | but the weird thing is we don't get the timeout event after 5 minutes | |
| 20:12:45 | mriedem | https://gist.githubusercontent.com/mheler/475d21b741aa58f320a456c3ac0d0f45/raw/ff76c45c3b6968b0d0514a9a7dcf478f054f6b70/gistfile1.txt | |
| 20:12:55 | mriedem | instance is c37d7489-a67b-47ea-a4f7-9323804cc552 | |
| 20:12:56 | dansmith | if it comes before we register it gets dropped, | |
| 20:12:59 | prometheanfire | that's the sender | |
| 20:13:09 | dansmith | but obviously the point is it's supposed to come after the register as you said | |
| 20:13:24 | mriedem | gets dropped but won't we wait for something that doesn't come and timeout? | |
| 20:13:39 | dansmith | should timeout yeah | |
| 20:13:50 | mriedem | the network-vif-plugged is triggered via plug_vifs during pre_live_migration on the dest, | |
| 20:13:57 | mriedem | which happens before his code runs to register the waiter | |
| 20:14:00 | mriedem | so it's a total race window | |
| 20:14:14 | dansmith | ugh | |
| 20:14:21 | mriedem | which is why we added https://github.com/openstack/nova/blob/master/nova/conf/compute.py#L675 | |
| 20:14:24 | mriedem | but not backportable | |
| 20:14:38 | dansmith | I thought it gets triggered by the actual guest starting on the other side, which came from the actual live migration op | |
| 20:14:52 | mriedem | i'd need sahid to confirm that | |
| 20:15:04 | mriedem | but network-vif-plugged, as far as i know, comes from plug_vifs on the dest during pre_live_migratoin | |
| 20:15:08 | mriedem | which is before his code runs | |
| 20:15:11 | mriedem | on the source | |
| 20:15:18 | dansmith | so, | |
| 20:15:30 | dansmith | the even comes from the tap being created actually | |
| 20:15:35 | dansmith | *event | |
| 20:16:16 | dansmith | so maybe plug is creating a tap before libvirt does but I'm not sure how we'd give it to it | |
| 20:16:44 | mriedem | prometheanfire: i'm assuming you have this https://review.openstack.org/#/c/586965/ | |
| 20:16:48 | mriedem | ^ fix for the pike backport | |
| 20:17:00 | prometheanfire | ya | |
| 20:17:07 | dansmith | I learned this after we were working on that patch though | |
| 20:17:10 | prometheanfire | that's within the sha I posted earlier | |
| 20:17:21 | prometheanfire | otherwise it wouldn't succeed at all :P | |
| 20:17:23 | openstackgerrit | Jay Pipes proposed openstack/nova master: placement: use simple code paths when possible https://review.openstack.org/590388 | |
| 20:17:24 | openstackgerrit | Jay Pipes proposed openstack/nova master: split gigantor SQL placement query into multiple https://review.openstack.org/590041 | |