| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2022-05-05 | |||
| 17:00:34 | mnaser | kill -USR2 <nova-pid> | |
| 17:00:35 | sean-k-mooney | Uggla: so for unshelve ot az it ends up updating the request spec to the requested az | |
| 17:00:40 | mnaser | grep -i 'Green Thread' /tmp/gar | wc -l => 6094 | |
| 17:01:04 | sean-k-mooney | mnaser: those are the userland trhead not real os thread | |
| 17:01:21 | mnaser | a lot of them are this: | |
| 17:01:25 | mnaser | https://www.irccloud.com/pastebin/YBiYPlrp/ | |
| 17:01:31 | mnaser | and i think the root cause is from https://www.irccloud.com/pastebin/n7Ezs7aB/ | |
| 17:02:22 | sean-k-mooney | Uggla: so for unshelve ot host i think it shoudl also update it to the AZ of the host if and only if the request spec is not none | |
| 17:02:26 | mnaser | so with every failure of this, we'd get an extra greenthread that sits and does nothing | |
| 17:02:39 | sean-k-mooney | Uggla: i need to think about that and make sure that is right | |
| 17:03:00 | sean-k-mooney | Uggla: bug basically if the vm orgringaly requested an AZ we want to update it to match the az of the host | |
| 17:03:11 | sean-k-mooney | Uggla: if it did not then we do not want to update it | |
| 17:03:16 | sean-k-mooney | Uggla: i think | |
| 17:04:12 | sean-k-mooney | mnaser: well that implies that nothing is catching the vif creation failure? | |
| 17:04:48 | sean-k-mooney | or its never been resumed | |
| 17:05:09 | mnaser | sean-k-mooney: maybe.. i've seen similar behaviour here https://github.com/eventlet/eventlet/issues/432 and https://github.com/eventlet/eventlet/issues/662 | |
| 17:05:11 | sean-k-mooney | im not really sure why you would end up with multiple dangeling thread like that | |
| 17:06:37 | mnaser | its supposed to log a warning if it hits that exception | |
| 17:06:45 | mnaser | let me see https://github.com/openstack/nova/blob/stable/wallaby/nova/virt/libvirt/driver.py#L7236-L7245 is logged | |
| 17:07:18 | sean-k-mooney | yes which would do io and cause the thread to yeild | |
| 17:07:32 | sean-k-mooney | *greenthread | |
| 17:07:50 | sean-k-mooney | or at least potentially while the python logger processes the logging event | |
| 17:09:58 | sean-k-mooney | mnaser: that looks promising and also depressing | |
| 17:10:13 | sean-k-mooney | i.e. that python logging is broken and has been for ever | |
| 17:10:16 | mnaser | sean-k-mooney: sadly it looks like the logs got rotated out :( | |
| 17:10:29 | mnaser | with the kill -USR2 it wiped a bunch of the old logs | |
| 17:10:58 | sean-k-mooney | are you using oslo.log's logrotation feature | |
| 17:11:09 | sean-k-mooney | or using logrotate externally | |
| 17:11:22 | mnaser | no, this is bc we run stuff inside k8s, so the max-log-size feature or whatever its called i believe hit here | |
| 17:11:27 | sean-k-mooney | kill -USR2 usually requires a process restart to recover form | |
| 17:11:59 | mnaser | to me it sounds like there should not be a traceback for this thing to start with | |
| 17:11:59 | sean-k-mooney | ack so dumping the GMR proably caused the pod to be restarted | |
| 17:13:43 | mnaser | this is wallaby blergh | |
| 17:14:12 | Uggla | sean-k-mooney, ok by the way we (with Artom) added some tests to ensure a cold migration after shelve/unshelve to host is moving back the host to the origin host. | |
| 17:15:24 | Uggla | sean-k-mooney, but we can discuss that tomorrow, it will let you think about it. | |
| 17:15:31 | mnaser | ok it looks like timeout was raised, then since `vif_plugging_is_fatal`, that raises another exception again, which bubbles back up to the `except Exception` | |
| 17:15:43 | mnaser | https://github.com/openstack/nova/blob/stable/wallaby/nova/virt/libvirt/driver.py#L7235-L7266 | |
| 17:16:32 | mnaser | then we LOG.error() the whole stack, which seems to add up | |
| 17:17:24 | sean-k-mooney | so its being rasised form here https://github.com/openstack/nova/blob/master/nova/virt/libvirt/driver.py#L7499= | |
| 17:17:24 | sean-k-mooney | so we plug the start a timer to with for the viff plugged event then we plug the vifs then we creat the guest | |
| 17:17:24 | sean-k-mooney | we start waiting in this context manager https://github.com/openstack/nova/blob/master/nova/virt/libvirt/driver.py#L7491-L7494= | |
| 17:17:24 | sean-k-mooney | that is timeing out after 300 seconds | |
| 17:17:24 | sean-k-mooney | causign this expct block to be taken | |
| 17:19:38 | mnaser | https://eventlet.net/doc/modules/timeout.html | |
| 17:19:42 | mnaser | "If the code block catches and doesn’t re-raise BaseException (for example, with except:), then it will catch the Timeout exception, and might not abort as intended." | |
| 17:19:42 | mnaser | "If the code block catches and doesn’t re-raise BaseException (for example, with except:), then it will catch the Timeout exception, and might not abort as intended." | |
| 17:19:46 | sean-k-mooney | if you have logs for this in the future you could proably check fo rthis log https://github.com/openstack/nova/blob/7520711a0e3b20354c0a9d46cb1dd62c8f56db24/nova/compute/manager.py#L559-L569= | |
| 17:20:49 | sean-k-mooney | mnaser: i dont think we are incorectly cathching this | |
| 17:24:08 | sean-k-mooney | hum https://github.com/openstack/nova/blob/7520711a0e3b20354c0a9d46cb1dd62c8f56db24/nova/compute/manager.py#L2202-L2242= | |
| 17:25:44 | sean-k-mooney | we are not using a threadpool here so this should be fine | |
| 17:25:50 | mnaser | i believ this issue surfaces if you have a lot of port plugging timeouts, which is why it might not be noticed | |
| 17:26:09 | mnaser | (i could solve this by figuring out why the ports are all timing out being plugged, since that is the cause, but still seems to be an issue) | |
| 17:26:31 | mnaser | i wonder if it can be reproduced by spinning up a bunch of instances with n-ovs-agent shut down for example | |
| 17:27:01 | sean-k-mooney | but it proably woudl be simpler to reproduce in teh func test | |
| 17:27:19 | sean-k-mooney | just mock out the part of the nueton fixture that sends the event | |
| 17:27:45 | sean-k-mooney | what i dont get is why is the thread not being resumed | |
| 17:28:31 | sean-k-mooney | it raising the excption (either timeour or vif plugged) but nothign is resuming the greenthreadn and its just waiting forever | |
| 17:28:41 | sean-k-mooney | i wonder if this because we use spawn_n | |
| 17:28:49 | sean-k-mooney | instead of spawn | |
| 17:30:02 | sean-k-mooney | mnaser: gibi mentioned something abtou this in a differnt context https://review.opendev.org/c/openstack/nova/+/825015/4/nova/healthcheck/manager.py#214= | |
| 17:32:19 | sean-k-mooney | maybe we shoudl be useing spawn here instead https://github.com/openstack/nova/blob/7520711a0e3b20354c0a9d46cb1dd62c8f56db24/nova/compute/manager.py#L2242-L2247 | |
| 17:35:15 | sean-k-mooney | mnaser: this is hte comment that gibi was intening i read i think | |
| 17:35:17 | sean-k-mooney | https://review.opendev.org/c/openstack/nova/+/813114/1..4//COMMIT_MSG#b19= | |
| 17:35:43 | sean-k-mooney | https://github.com/eventlet/eventlet/issues/731#issuecomment-953761883 | |
| 17:35:59 | kashyap | gibi: I need to head out, but I see that you've got a new rev up w/ a new package removals. And Zuul seems to be happy. Will check tomm :) | |
| 17:38:08 | sean-k-mooney | melwitt: you might also have context on mnaser greenthread leaking issue | |
| 17:38:42 | sean-k-mooney | melwitt: is there a reason that you are aware of to not remvoe all uses of spawn_n and replace them with spawn? | |
| 17:40:33 | sean-k-mooney | we likely woudl have to add https://github.com/eventlet/eventlet/issues/731#issuecomment-953761883 to our monkey patch file | |
| 17:40:42 | sean-k-mooney | to cater for the thread.start case you noted | |
| 17:40:49 | melwitt | sean-k-mooney: no, temoto recommended not to use spawn_n | |
| 17:41:15 | sean-k-mooney | yep reading the bug that is clear | |
| 17:41:33 | sean-k-mooney | so we coudl replace all the calls and also do | |
| 17:41:37 | melwitt | I did do a patch to change them all but we still had some come up bc for example oslo.messaging uses spawn_n when in eventlet mode | |
| 17:41:40 | sean-k-mooney | import eventlet | |
| 17:41:42 | sean-k-mooney | eventlet.spawn_n = eventlet.spawn | |
| 17:41:44 | sean-k-mooney | eventlet.convenient.spawn_n = eventlet.spawn | |
| 17:41:46 | sean-k-mooney | eventlet.monkey_patch() | |
| 17:42:08 | sean-k-mooney | melwitt: right but if we gloablly repoalce spawn_n with spawn | |
| 17:42:12 | sean-k-mooney | when we monkey patch | |
| 17:42:20 | sean-k-mooney | the oslo will also start using spwan | |
| 17:42:28 | sean-k-mooney | although we probly shoudl fix it in oslo too | |
| 17:42:30 | melwitt | ah, true. I was thinking of when I tried literally changing them all + a hacking rule | |
| 17:42:40 | melwitt | +1 | |
| 17:43:03 | sean-k-mooney | did you ever raise that with oslo? | |
| 17:43:13 | sean-k-mooney | removing there use of spawn_n | |
| 17:43:59 | melwitt | no. at the time I was so mired in trying to sort the eventlet issue that I didn't think to initiate that | |
| 17:44:53 | sean-k-mooney | ack | |
| 17:45:08 | sean-k-mooney | it looks like spawn_n is pretty common in openstack | |
| 17:45:10 | sean-k-mooney | https://codesearch.opendev.org/?q=spawn_n&i=nope&literal=nope&files=&excludeFiles=&repos= | |
| 17:45:31 | melwitt | I had also intended to put together a more concise repro of the spawn_n problematic behavior to do another eventlet issue but lost steam | |
| 17:45:46 | melwitt | yeah I was thinking that might be the case. I probably checked back then and then forgot | |
| 17:47:18 | sean-k-mooney | so this could be a redherring as to why nothing seams to be resuming the greenthread after the excption is raised when there i s a netowk vif plugged | |
| 17:47:26 | sean-k-mooney | event that fails | |
| 17:47:33 | mnaser | so probably the spawn_n here is causing this somehow ? | |
| 17:47:50 | sean-k-mooney | mnaser: thats what im specualting but not sure | |
| 17:48:04 | sean-k-mooney | im wondiering if we just spawned a fucntion taht raise woudl that trigger this | |
| 17:50:26 | sean-k-mooney | anyway i need to go fo today but it might be worth tryign to repoduce this outside fo nova with a simpel script that use eventles swan_n and raises | |
| 17:50:53 | sean-k-mooney | https://eventlet.net/doc/basic_usage.html#eventlet.spawn_n | |
| 17:50:56 | mnaser | yeah.. I don’t know if I have spare cycles right now for that but I think I should probably file a bug in launchpad at least | |
| 17:50:58 | sean-k-mooney | The same as spawn(), but it’s not possible to know how the function terminated (i.e. no return value or exceptions). This makes execution faster. See spawn_n for more details. | |