| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2023-07-27 | |||
| 18:21:39 | gmann | frickler: every API call go through the request only either post, delete etc | |
| 18:22:10 | gmann | sean-k-mooney: I am saying in tempest it get 200 and empty output right? | |
| 18:22:25 | sean-k-mooney | https://github.com/openstack/nova/blob/e5ee5e035c0c85654a139131d51be5c4df76f400/nova/api/openstack/compute/console_output.py#L56-L58 | |
| 18:23:00 | sean-k-mooney | gmann: i dont see how it could be getting a 200 in tempest | |
| 18:23:30 | gmann | so _error_checker pass and self.assertTrue(output, "Console output was empty.") is valid assert right | |
| 18:23:38 | sean-k-mooney | i guess if we have the request id i can check in the job logs | |
| 18:24:14 | sean-k-mooney | gmann: that is the assert that is failing i belive yes | |
| 18:24:37 | sean-k-mooney | yes see the bug https://bugs.launchpad.net/nova/+bug/2028851 | |
| 18:24:53 | gmann | yeah I am checking those only | |
| 18:25:33 | sean-k-mooney | oh... | |
| 18:26:04 | gmann | because this is alst call to get console from tempest which return 200 and empty output https://zuul.opendev.org/t/openstack/build/9890c9b53059410eabc0c61df0376217/log/controller/logs/tempest_log.txt#40163 | |
| 18:26:40 | sean-k-mooney | the isntance is still active | |
| 18:26:47 | sean-k-mooney | its ment to be stopped | |
| 18:27:17 | gmann | even every call on wait is same 200 and empty output https://zuul.opendev.org/t/openstack/build/9890c9b53059410eabc0c61df0376217/log/controller/logs/tempest_log.txt#39248-40163 | |
| 18:29:07 | gmann | and while waiting for non empty console output, tempest timeout and raise exception from that assert https://github.com/openstack/tempest/blob/04cb0adc822ffea6c7bfccce8fa08b03739894b7/tempest/api/compute/base.py#L340 | |
| 18:29:35 | sean-k-mooney | it should not have got there | |
| 18:29:43 | sean-k-mooney | https://github.com/openstack/tempest/blob/04cb0adc822ffea6c7bfccce8fa08b03739894b7/tempest/api/compute/servers/test_server_actions.py#L727C7-L727C79 | |
| 18:29:55 | sean-k-mooney | that was ment to be wating for the instance ot be shutoff | |
| 18:31:28 | sean-k-mooney | so i see 2023-07-27 14:03:23,945 91441 INFO [tempest.common.waiters] State transition "ACTIVE/powering-off" ==> "SHUTOFF/None" after 1 second wait | |
| 18:31:51 | gmann | sean-k-mooney: it does and server is in shutoff state only https://zuul.opendev.org/t/openstack/build/9890c9b53059410eabc0c61df0376217/log/controller/logs/tempest_log.txt#39246 | |
| 18:32:15 | gmann | after that only it check for the console output | |
| 18:34:53 | frickler | so maybe this is a race? I wonder if you sleep a bit after the wait-for-shutoff whether it would always fail with 404 | |
| 18:34:58 | sean-k-mooney | so the server uuid is e526f14e-5878-4fab-ba8b-4f6c2456bd2 so we shoud lbe able to confirm the status code in the api logs | |
| 18:35:22 | sean-k-mooney | frickler: i have the vm stopped on my local devstack and it fails with 404 yes | |
| 18:36:16 | sean-k-mooney | in ci it looks like its getting 200's for about 3 minutes | |
| 18:36:37 | sean-k-mooney | but i get a 404 basically imiedaly after i power it off | |
| 18:38:08 | frickler | https://zuul.opendev.org/t/openstack/build/9890c9b53059410eabc0c61df0376217/log/controller/logs/screen-n-api.txt#34450 | |
| 18:38:43 | frickler | can you run console log show in a loop while you power off? also are you on a lvm setup? | |
| 18:41:53 | sean-k-mooney | i have it in a watch now | |
| 18:41:59 | sean-k-mooney | but its consitently 404 | |
| 18:45:25 | sean-k-mooney | POST /compute/v2.1/servers/e526f14e-5878-4fab-ba8b-4f6c2456bd2a/action => generated 14 bytes in 66 msecs (HTTP/1.1 200) 9 headers in 356 bytes (1 switches on core 0) | |
| 18:45:34 | sean-k-mooney | in ci its getting a 200 | |
| 18:45:57 | frickler | one other thing I don't understand is why this is wrapped in a wait_for() https://github.com/openstack/tempest/blob/04cb0adc822ffea6c7bfccce8fa08b03739894b7/tempest/api/compute/servers/test_server_actions.py#L728 | |
| 18:46:16 | frickler | _get_output() either asserts or returns nothing, right? | |
| 18:47:00 | sean-k-mooney | your right | |
| 18:47:04 | sean-k-mooney | it never returns anything | |
| 18:47:47 | frickler | oh, wait. _get_server acts on self.server_id not on temp_server_id | |
| 18:47:50 | gmann | frickler: sean-k-mooney dansmith melwitt: ahh I got the issue here. we are using different server in that tests not the one test create :( https://github.com/openstack/tempest/blob/04cb0adc822ffea6c7bfccce8fa08b03739894b7/tempest/api/compute/servers/test_server_actions.py#L212 | |
| 18:47:58 | gmann | and test use differnt server https://github.com/openstack/tempest/blob/04cb0adc822ffea6c7bfccce8fa08b03739894b7/tempest/api/compute/servers/test_server_actions.py#L723-L728 | |
| 18:47:59 | frickler | gmann: ^5 | |
| 18:48:07 | melwitt | wuuuut | |
| 18:48:14 | gmann | frickler: yeah | |
| 18:48:22 | gmann | diffeent server id in both place in log https://zuul.opendev.org/t/openstack/build/9890c9b53059410eabc0c61df0376217/log/controller/logs/tempest_log.txt#39246-39248 | |
| 18:48:26 | gmann | fixing it | |
| 18:48:38 | gmann | just a 4 letter mistake and took so much time :) | |
| 18:48:48 | melwitt | wow. fr | |
| 18:48:50 | sean-k-mooney | oh we are not passign a server id to _get_output | |
| 18:49:03 | sean-k-mooney | i checked the ides that were in use | |
| 18:49:15 | sean-k-mooney | but i missed we did not pass it to _get_output | |
| 18:49:18 | gmann | both are different https://zuul.opendev.org/t/openstack/build/9890c9b53059410eabc0c61df0376217/log/controller/logs/tempest_log.txt#39246-39248 | |
| 18:50:03 | sean-k-mooney | gmann: but that does not explain why its working for ceph | |
| 18:50:21 | sean-k-mooney | oh unless the first vm | |
| 18:50:25 | sean-k-mooney | is not active | |
| 18:50:35 | sean-k-mooney | by the time we get to this? | |
| 18:50:38 | gmann | sean-k-mooney: might be that different server used in get_console is created in setup so it has the console output | |
| 18:50:53 | sean-k-mooney | or that ya | |
| 18:50:59 | sean-k-mooney | its runing longer | |
| 18:51:06 | gmann | yeah | |
| 18:51:18 | sean-k-mooney | well its more you only get the 404 if its stopped | |
| 18:52:24 | sean-k-mooney | gmann: are you workign on a pathch to optionally pass the server id to _get_output | |
| 18:52:33 | gmann | sean-k-mooney: yeah | |
| 18:53:15 | gmann | running the test | |
| 18:53:36 | sean-k-mooney | the test sill still not be really correct | |
| 18:54:42 | frickler | the test should start failing if this is fixed, because it should get 404s all the time | |
| 18:55:03 | frickler | so the question is whether nova is broken or the test | |
| 18:55:03 | sean-k-mooney | yep | |
| 18:55:18 | sean-k-mooney | both kind of | |
| 18:55:34 | sean-k-mooney | nova could be maded to work when the vm is stopped in this case | |
| 18:55:51 | sean-k-mooney | but the test is not correct today either | |
| 18:55:58 | gmann | why ? | |
| 18:56:26 | gmann | nova should return 404 or something if no actual console is get or maybe correct if empty console for shutoff VM is ok | |
| 18:56:37 | gmann | but I do not see why test is incorrect | |
| 18:56:52 | gmann | or should we expect empty console for shutoff VM as valid case? | |
| 18:56:58 | sean-k-mooney | because its going to be asserting that "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." is true | |
| 18:57:28 | sean-k-mooney | the test is ment to be asserting that you can retirve the concole log while the vm is stopped | |
| 18:58:20 | sean-k-mooney | that works on my home cloud which is using cinder BFV | |
| 18:58:56 | sean-k-mooney | so there is a bug in nova as this should work | |
| 18:59:40 | sean-k-mooney | if the test catches that then the test is ok but it shoudl be failing when using the correct server id | |
| 19:00:06 | sean-k-mooney | in the lvm job | |
| 19:00:28 | sean-k-mooney | so we shoudl retirage https://bugs.launchpad.net/nova/+bug/2028851 | |
| 19:00:40 | sean-k-mooney | its a valid bug for both nova and tempest | |
| 19:00:58 | sean-k-mooney | dansmith: melwitt: do you agree ^ | |
| 19:01:47 | sean-k-mooney | on the nova side we either need to say the console shoudl always be aviable for all dirver when the server is off | |
| 19:01:55 | sean-k-mooney | or that test is invalid for nova-lvm | |
| 19:02:07 | melwitt | I'm a little confused but if the tempest test is passing with the correct server id with a 404 being returned from nova then the tempest test has a bug as well | |
| 19:02:24 | sean-k-mooney | no i think that will fail | |
| 19:02:38 | sean-k-mooney | the only tempest bug is the one gmann found where its not using the correct id | |
| 19:02:51 | melwitt | oh gotcha. yeah. I agree there is a bug on nova too | |
| 19:04:01 | gmann | https://review.opendev.org/c/openstack/tempest/+/889895 | |
| 19:04:45 | dansmith | 404 should mean "that path you gave me does not exist | |
| 19:04:48 | gmann | melwitt: sean-k-mooney yeah i will fail, I tested locally and got the 404 from nova, tempest failed | |
| 19:05:03 | dansmith | 404 for a POST doing an action that doesn't return anything but for a guest that does exist is extremely wrong, IMHO | |
| 19:05:35 | dansmith | especially when the same POST url just worked for shutdown and will work a minute later for start up | |
| 19:05:40 | gmann | dansmith: yes it says 404 Guest does not have a console available | |
| 19:05:57 | dansmith | right, that is incorrect HTTP behavior, IMHO | |
| 19:05:57 | sean-k-mooney | dansmith: its kind of abusing 404 right now | |
| 19:06:06 | dansmith | yeah | |
| 19:06:10 | sean-k-mooney | but i can see why someone might have chosen it | |
| 19:06:16 | sean-k-mooney | i.e. the log was nto found | |
| 19:06:17 | gmann | maybe 400 we should return | |