| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2023-07-27 | |||
| 16:58:22 | sean-k-mooney | did ye fined anything in the intrim | |
| 16:58:39 | sean-k-mooney | the content is still there on disk for what its worth | |
| 17:00:57 | sean-k-mooney | stack@upstream-devstack:~/repos/devstack$ openstack console log show test | |
| 17:00:59 | sean-k-mooney | ResourceNotFound: 404: Client Error for url: http://192.168.122.17/compute/v2.1/servers/ea890cd1-c3fe-4455-bcd9-b44ea830a136/action, Guest does not have a console available. | |
| 17:03:09 | sean-k-mooney | oh... | |
| 17:03:25 | sean-k-mooney | Fetching instance by UUID {{(pid=1349614) get /opt/stack/nova/nova/compute/api.py:2978 | |
| 17:05:21 | sean-k-mooney | ok that is not relevent its just https://github.com/openstack/nova/blob/master/nova/compute/api.py#L2978-L2982 | |
| 17:05:41 | dansmith | melwitt: so to be clear, you've got regular guests with pty consoles yeah? | |
| 17:06:01 | sean-k-mooney | [None req-0042b3bd-d199-4c9d-b8f2-f1ee3a2d444e demo admin] HTTP exception thrown: Guest does not have a console available. | |
| 17:06:06 | dansmith | I wonder if this was the fix for the "console log grows forever" problem and my (our?) assumptions that it's still just a file on disk is old | |
| 17:06:45 | dansmith | if that's so, I don't see how we'd ever pass that test once we remove the races, if we don't get the console log once while it's running | |
| 17:07:18 | sean-k-mooney | so there is a file on disk | |
| 17:08:12 | dansmith | right, but the code in libvirt driver is feeding it from the pty each time it runs | |
| 17:09:29 | melwitt | ok, so what's happening is the xml for <console> element is different after the instance is stopped | |
| 17:09:45 | melwitt | so the parsing it's doing is not finding the console path | |
| 17:11:32 | melwitt | before the instance is stopped, there's <source path='/dev/pts/3'/> under console. after the instance is stopped there is not | |
| 17:11:34 | melwitt | and it's looking for this ('pty', "./devices/console[@type='pty']/source[@path]", 'path') | |
| 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 | |