| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2023-07-27 | |||
| 17:11:48 | sean-k-mooney | https://paste.opendev.org/show/bU3Vb2zX0TgOqU42xBAV/ | |
| 17:12:11 | sean-k-mooney | it is be we have the log file line in both cases | |
| 17:12:26 | sean-k-mooney | so we shoudl be usign that not source | |
| 17:12:57 | sean-k-mooney | or at least falling back to the log line if source is not found | |
| 17:13:07 | melwitt | https://paste.openstack.org/show/bnLH5aJxsHlzXdZS455s/ | |
| 17:13:30 | melwitt | yeah, I think that's the bug | |
| 17:13:35 | melwitt | it's not falling back | |
| 17:13:51 | sean-k-mooney | well i think log is alwasy where to im not sure if the fallback is ever needed | |
| 17:14:14 | sean-k-mooney | i woudl be incliend to prefer log and fallback ot source if its not there | |
| 17:14:44 | melwitt | the log file is always there. it's just using source only | |
| 17:15:22 | melwitt | it looks like the code intends to fall back to the file but it's not working | |
| 17:15:30 | sean-k-mooney | we also have https://github.com/openstack/nova/blob/master/nova/virt/libvirt/driver.py#L4577C1-L4580C43 | |
| 17:15:36 | sean-k-mooney | we are generating what that will be | |
| 17:15:42 | sean-k-mooney | we dont ever need to parse the xml | |
| 17:15:46 | dansmith | so the test not waiting for sshable was actually the reason this never failed? because we were racing with the shutdown? | |
| 17:16:04 | melwitt | hah probably | |
| 17:16:11 | melwitt | I dunno | |
| 17:16:20 | dansmith | I guess I don't know why this is only failing lvm still, unless it's just lvm being slower or faster about something? | |
| 17:16:31 | melwitt | yeah that's what I don't understand | |
| 17:17:37 | melwitt | I would have wondered if console type is not pty if not lvm but my setup is rbd and I get console type pty.. and the ceph job isn't failing this test iiuc | |
| 17:18:11 | dansmith | right | |
| 17:18:14 | sean-k-mooney | i think its a pty when virtlogd is installed and running | |
| 17:18:36 | sean-k-mooney | qemu is using the pty to talk to virtlogd which is writing to the file | |
| 17:18:38 | sean-k-mooney | i think | |
| 17:19:15 | sean-k-mooney | but i dont see why we woudl ever need to read form that. we can simplfy this code by using | |
| 17:19:20 | sean-k-mooney | _get_console_log_path(instance) | |
| 17:19:28 | sean-k-mooney | to return the log file and just read directly form that | |
| 17:20:21 | melwitt | yeah I dunno if there is or was a reason for doing the reading from pty | |
| 17:21:19 | sean-k-mooney | https://github.com/openstack/nova/blob/master/nova/virt/libvirt/driver.py#L4462-L4488 | |
| 17:21:31 | sean-k-mooney | so this is doub | |
| 17:21:43 | sean-k-mooney | we use console_log = self._get_console_log_path(instance) | |
| 17:22:00 | sean-k-mooney | to get the path which is to the file but that not the path we check for at the start | |
| 17:22:31 | sean-k-mooney | oh actully | |
| 17:23:01 | sean-k-mooney | https://github.com/openstack/nova/blob/master/nova/virt/libvirt/driver.py#L4487-L4502 | |
| 17:23:34 | sean-k-mooney | we read form the pty and write to the log and then read form the log again but this time without privsep | |
| 17:24:29 | melwitt | this is like rube goldberg | |
| 17:24:51 | sean-k-mooney | ok so if i tail the log file and start the vm it gets the stream | |
| 17:25:01 | sean-k-mooney | so we dont actully need to write to the logfile | |
| 17:25:12 | sean-k-mooney | it already has the data form the pty | |
| 17:25:53 | sean-k-mooney | and shutting off the instance dow not affect the data | |
| 17:26:34 | melwitt | what about if the compute host were to be rebooted? just trying to think if there's any case where we need the file | |
| 17:26:58 | sean-k-mooney | the file is beiing wrttien by qemu/virtlogd | |
| 17:27:16 | sean-k-mooney | its only written by use if we do a console log show | |
| 17:27:27 | melwitt | oh ok | |
| 17:27:36 | sean-k-mooney | so if we removed that code from nova it would already have the data | |
| 17:28:19 | sean-k-mooney | i did sudo tail -F console.log to confirm that | |
| 17:28:32 | dansmith | sean-k-mooney: certainly we need to not be reading from that pty if virtlogd is already doing it | |
| 17:28:34 | sean-k-mooney | when the vm starts it recreates the file | |
| 17:28:51 | dansmith | so where in there are we only doing that if virtlogd is not? | |
| 17:29:25 | sean-k-mooney | so is this part of the xml generated by libvirt or us | |
| 17:29:53 | sean-k-mooney | i tought we were just setting the log location and libvirt filled in the rest based on if virtlogd was deployed and how it was configured | |
| 17:30:21 | dansmith | not sure that matters, since this is on get and doesn't know if we added it or libvirt itself did right? | |
| 17:30:44 | sean-k-mooney | well we are specifying the location of the file | |
| 17:30:53 | sean-k-mooney | so my point is i think we can ignore if its a pty or not | |
| 17:30:58 | sean-k-mooney | and alwasy just go to the file | |
| 17:31:09 | dansmith | not here.. here we're just looking at the state of the xml | |
| 17:31:23 | sean-k-mooney | but we dont need to look at the xml at all | |
| 17:31:39 | sean-k-mooney | thats my point we have a function that takes the instance and returs the log path to use | |
| 17:31:49 | sean-k-mooney | its always called consol.log in the instnace dir | |
| 17:31:54 | dansmith | I know that's your point, I'm just not sure it's right :) | |
| 17:32:04 | sean-k-mooney | ok :) | |
| 17:32:14 | dansmith | I want to know how we're not tripping over us reading from the pty when virtlogd already is | |
| 17:32:40 | sean-k-mooney | ah good question | |
| 17:32:46 | dansmith | I mean I guess if virtlogd is select()ing from it then it has already read everything we potentially could have from the pty each time we go to read from it, and we just get lucky that we never compete | |
| 17:33:01 | dansmith | but I would expect to occasionally see some corruption there | |
| 17:33:26 | dansmith | and is virtlogd always a thing in libvirt now, or is it optional? | |
| 17:33:37 | dansmith | and even still, | |
| 17:33:54 | dansmith | it looks to me like we *are* always returning the contents of the file at the bottom of that function, | |
| 17:34:09 | sean-k-mooney | https://paste.opendev.org/show/bW8SNwHjfUFkOMv4gp5N/ | |
| 17:34:10 | dansmith | so why are we getting blank log output when the file on disk clearly has stuff in it? | |
| 17:34:15 | sean-k-mooney | that is the orginal xml we generate | |
| 17:34:38 | sean-k-mooney | there is no console element at all we just set the serial port and pass the log path | |
| 17:34:40 | dansmith | that has no console stuff in it and is not complete | |
| 17:34:51 | sean-k-mooney | no i just didn copy it all one sec | |
| 17:35:09 | dansmith | but I don't see what it matters what we generate | |
| 17:35:15 | sean-k-mooney | https://paste.opendev.org/show/bdwD3vAg5f6D6iNsIHk1/ | |
| 17:35:33 | melwitt | it's relying on <source> in the xml to get the console path, so it gets no path at all | |
| 17:36:01 | sean-k-mooney | we are telling libvirt to do whatever it need to to make sure teh serial console is in a given file | |
| 17:36:03 | dansmith | melwitt: oh okay, gotcha you said that earlier I think | |
| 17:36:30 | dansmith | okay, so if we ask for pty/logfile and rely on virtlogd now it sounds like | |
| 17:36:33 | sean-k-mooney | i think we shoudl be changing this code to only use that instaed | |
| 17:36:46 | dansmith | so the comment in the code there about ptys says something about container types, | |
| 17:36:57 | dansmith | presumably because they will hang a process if something doesn't consume their pty | |
| 17:37:17 | dansmith | so perhaps that code is leftover from long ago before we moved to virtlogd everywhere, and that all needs to be ripped out? | |
| 17:37:20 | melwitt | I did but I know it's hard to visualize. here's my dumb print statements showing how it goes https://paste.openstack.org/show/bpovXD89OL2QzukI3BWi/ | |
| 17:37:26 | sean-k-mooney | he virt_types kvm and qemu are the only ones | |
| 17:37:28 | sean-k-mooney | # which create a dedicated file device for the console logging. | |
| 17:37:33 | sean-k-mooney | ok | |
| 17:37:35 | dansmith | keep reaing | |
| 17:37:38 | dansmith | *reading | |
| 17:37:46 | sean-k-mooney | so the pty fallback is for other virt drivers | |
| 17:37:58 | sean-k-mooney | not driver virt types like lxc | |
| 17:38:10 | dansmith | it says "like lxc" | |
| 17:38:15 | sean-k-mooney | yep | |
| 17:38:28 | dansmith | you said "not virt types like lxc" | |
| 17:38:37 | sean-k-mooney | so if virt_type not in (qemu,kvm) | |
| 17:38:47 | sean-k-mooney | then we need to read from the pty | |
| 17:38:51 | sean-k-mooney | and save it to a file | |
| 17:38:57 | sean-k-mooney | but for qemu/kvm we dont | |
| 17:39:22 | dansmith | anyway, it makes me super nervous to mess with stuff like this without a very clear understanding of what is going on, and I *still* don't understand why this isn't always failing especially after sean-k-mooney's change to the test | |