| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2023-07-27 | |||
| 16:06:06 | melwitt | the console log file path in the xml is correct and I can use it to open the log file | |
| 16:06:09 | sean-k-mooney | https://paste.opendev.org/show/bMa9I7WsUnEfsrMC6iQz/ | |
| 16:06:45 | melwitt | is the console log get API working for you? | |
| 16:07:06 | sean-k-mooney | i did it in horizon but ill check in a sec on the cli | |
| 16:07:27 | sean-k-mooney | horizon is now showing "Unable to get log for instance "ea890cd1-c3fe-4455-bcd9-b44ea830a136"." | |
| 16:08:14 | dansmith | melwitt: interesting, I started with libvirt before there were even non-active domains and definitely since before uuids were in the xml, so I guess 15-year habits die hard :) | |
| 16:08:40 | melwitt | for mine there's helpfully no log messages that say anything about why/where it's running into a problem | |
| 16:08:43 | dansmith | ahh, console type is pty, | |
| 16:08:49 | dansmith | that's what I was wondering if it was happening | |
| 16:09:03 | dansmith | the comment says it's only for container types, but it would explain why we're losing console on shutdown | |
| 16:09:28 | dansmith | so with pty, there's no storage of the console stuff once the other side goes away, like when shutdown | |
| 16:09:36 | melwitt | I feel like it has to be this failing: data = nova.privsep.libvirt.readpty(console_path) | |
| 16:10:05 | dansmith | melwitt: your console path is a file or a path to a pty? | |
| 16:10:26 | melwitt | it's a file. but it is also type pty. which I assume is not right? | |
| 16:10:36 | dansmith | idk, to be honest | |
| 16:10:55 | sean-k-mooney | on a call by the way | |
| 16:10:56 | dansmith | the code looks like nova reads directly from the pty if the type is pty, so the file wouldn't be used | |
| 16:11:21 | dansmith | ah, wait, | |
| 16:11:32 | melwitt | the console files are there and are properly with data | |
| 16:11:32 | dansmith | it looks like it reads from the pty and writes the file if type=pty | |
| 16:11:40 | dansmith | but that would only work when it's running | |
| 16:12:10 | dansmith | so I wonder if the test is now breaking because we never read the log before the instance is shutdown (which is what the test was supposed to be doing) | |
| 16:12:11 | melwitt | oh hm ok, it must be bc I queried for the console before I shut it down | |
| 16:12:21 | melwitt | I'll try not querying before | |
| 16:12:29 | dansmith | if we did once, then it would write the file and then we could read the file after it's shutdown | |
| 16:12:46 | dansmith | so maybe the test just needs to hit the console endpoint once after ssh'able and then shutdown, and verify that it still works after | |
| 16:13:09 | melwitt | yeah.. for me I still can't get it via the API despite the fact that the file is there and the file path matches what's in the xml | |
| 16:13:54 | dansmith | is the domain inactive? | |
| 16:13:58 | melwitt | yes | |
| 16:14:07 | dansmith | I would think the console element would go away partially while inactive, | |
| 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 | |