| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2023-07-27 | |||
| 16:14:10 | dansmith | but is that causing us to not read from the file? | |
| 16:14:49 | melwitt | </console> | |
| 16:14:49 | melwitt | <target type='serial' port='0'/> | |
| 16:14:49 | melwitt | <log file='/opt/stack/data/nova/instances/682931e5-4563-4955-a552-526a31c6957a/console.log' append='off'/> | |
| 16:14:49 | melwitt | <console type='pty'> | |
| 16:15:03 | melwitt | and that file is right. it just can't get it for whatever reason | |
| 16:15:07 | dansmith | yeah | |
| 16:15:11 | dansmith | lemme re-read this code, hang on | |
| 16:15:40 | dansmith | okay so if it's a pty, we read anything from it we can and append to the log, | |
| 16:16:07 | dansmith | I guess so that we're constantly pulling pty content and filling the log file, and then we just "should" be returning the log file contents for the requester | |
| 16:16:38 | dansmith | melwitt: can you just add some logs to those functions and see what's going on? | |
| 16:16:55 | melwitt | yeah | |
| 16:58:04 | sean-k-mooney | ok call done | |
| 16:58:14 | sean-k-mooney | i was going to check the cli | |
| 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/ | |