| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2023-07-27 | |||
| 17:58:19 | melwitt | seasoned curlies | |
| 17:58:39 | dansmith | frickler: I'm kidding of course, just .. not our best moment :) | |
| 17:59:14 | frickler | well I can't say I'm not enjoying it ;) | |
| 17:59:18 | dansmith | lol | |
| 17:59:49 | melwitt | this means not an empty string no? | |
| 17:59:49 | melwitt | DEBUG nova.api.openstack.wsgi [None req-2441eccd-ea63-4c9d-94a3-29aaf1ecf5c4 demo demo] Returning 404 to user: Guest does not have a console available. {{(pid=2011570) __call__ /opt/stack/nova/nova/api/openstack/wsgi.py:936}} | |
| 18:00:19 | melwitt | I guess I should do osc --debug | |
| 18:00:25 | sean-k-mooney | status: 404 len: 86 microversion: 2.91 time: 0.719216 | |
| 18:00:42 | melwitt | RESP BODY: {"itemNotFound": {"code": 404, "message": "Guest does not have a console available."}} | |
| 18:00:44 | sean-k-mooney | 86 bytes might just be the header | |
| 18:00:49 | gmann | status code is already checked in service client side so we can just remove this assert itself ? | |
| 18:00:54 | sean-k-mooney | oh actully no | |
| 18:00:58 | sean-k-mooney | RESP BODY: {"itemNotFound": {"code": 404, "message": "Guest does not have a console available."}} | |
| 18:01:11 | melwitt | so I think it really is going assertTrue("Guest does not have a console available.") | |
| 18:01:32 | sean-k-mooney | ya but why whoudl that be false | |
| 18:01:45 | dansmith | maybe it's ... AI... | |
| 18:01:48 | melwitt | maybe for lvm it's not returning a non empty string? I dunno why | |
| 18:01:57 | melwitt | AI yes | |
| 18:02:03 | sean-k-mooney | no that form lvm | |
| 18:02:09 | sean-k-mooney | i have it repoduced locally | |
| 18:02:11 | melwitt | oh... uh wtf | |
| 18:02:28 | sean-k-mooney | i ran osc with --debug | |
| 18:02:38 | sean-k-mooney | so it pring the actul repsocne body | |
| 18:03:13 | gmann | but how come it reach to this assert if it return 404 ? it should have failed here https://github.com/openstack/tempest/blob/master/tempest/lib/api_schema/response/compute/v2_1/servers.py#L456 | |
| 18:03:56 | sean-k-mooney | thats the fully output if your interested form osc https://termbin.com/fq3i | |
| 18:04:05 | dansmith | gmann: yeah I was looking to see if we were ignoring 404 or something but we're not | |
| 18:04:40 | melwitt | I don't get how this is passing though | |
| 18:04:40 | melwitt | lines = len(output.split('\n')) | |
| 18:04:40 | melwitt | self.assertEqual(lines, 3) | |
| 18:04:50 | gmann | yeah, status code in resposne schema fail if different status code than expected and it does not proceed further | |
| 18:05:33 | melwitt | this is some kind of black magic I think | |
| 18:05:47 | dansmith | obviously the solution is to remove the nova-lvm job | |
| 18:06:11 | melwitt | yeah. removing job and skipping tests makes things work :D | |
| 18:06:34 | gmann | :) | |
| 18:06:39 | melwitt | we definitely need more logging in that tempest test cause like... lol | |
| 18:08:11 | sean-k-mooney | we only validate if the respocne is scculs or redirection | |
| 18:08:13 | sean-k-mooney | https://github.com/openstack/tempest/blob/04cb0adc822ffea6c7bfccce8fa08b03739894b7/tempest/lib/common/rest_client.py#L1016 | |
| 18:08:24 | sean-k-mooney | we got a 404 | |
| 18:08:30 | sean-k-mooney | so the cleint does not validate it | |
| 18:08:57 | sean-k-mooney | that why its not failing earlier | |
| 18:09:04 | melwitt | and there's no else: noice | |
| 18:09:18 | sean-k-mooney | yep we fall off the end of the function | |
| 18:09:25 | melwitt | VALID@ | |
| 18:09:29 | melwitt | VALID! | |
| 18:12:18 | gmann | sean-k-mooney: it should have failed here https://github.com/openstack/tempest/blob/04cb0adc822ffea6c7bfccce8fa08b03739894b7/tempest/lib/common/rest_client.py#L852 | |
| 18:13:17 | sean-k-mooney | i assume _error_checker is a decortor or called else whewer | |
| 18:13:26 | sean-k-mooney | i didnt see that in the funcitons i was looking at | |
| 18:14:02 | sean-k-mooney | thats not called form action https://github.com/openstack/tempest/blob/04cb0adc822ffea6c7bfccce8fa08b03739894b7/tempest/lib/services/compute/servers_client.py#L218 | |
| 18:14:19 | sean-k-mooney | or get_console_output https://github.com/openstack/tempest/blob/04cb0adc822ffea6c7bfccce8fa08b03739894b7/tempest/lib/services/compute/servers_client.py#L648-L656 | |
| 18:14:57 | sean-k-mooney | which is what we are calling https://github.com/openstack/tempest/blob/04cb0adc822ffea6c7bfccce8fa08b03739894b7/tempest/api/compute/servers/test_server_actions.py#L211 | |
| 18:16:00 | gmann | it is called for every API call from tempest https://github.com/openstack/tempest/blob/04cb0adc822ffea6c7bfccce8fa08b03739894b7/tempest/lib/common/rest_client.py#L742 | |
| 18:16:33 | sean-k-mooney | so its called form this post https://github.com/openstack/tempest/blob/04cb0adc822ffea6c7bfccce8fa08b03739894b7/tempest/lib/services/compute/servers_client.py#L225C27-L225C31 | |
| 18:16:45 | frickler | only success is validated https://github.com/openstack/tempest/blob/04cb0adc822ffea6c7bfccce8fa08b03739894b7/tempest/lib/common/rest_client.py#L1016 | |
| 18:17:37 | sean-k-mooney | ya but gmann is correct | |
| 18:18:09 | sean-k-mooney | on https://github.com/openstack/tempest/blob/04cb0adc822ffea6c7bfccce8fa08b03739894b7/tempest/lib/common/rest_client.py#L742 we shoudl go to _error_checker | |
| 18:18:20 | gmann | that is for schema only tempest validate status code and it is <400 then only it proceed to test otherwise fail in API call itself | |
| 18:18:34 | gmann | that->validate_response | |
| 18:19:59 | sean-k-mooney | ok so the post will raise | |
| 18:20:01 | sean-k-mooney | raise exceptions.NotFound(resp_body, resp=resp) | |
| 18:20:02 | gmann | i cannot see where getConsoleOutput return 400, it was always 200 https://zuul.opendev.org/t/openstack/build/9890c9b53059410eabc0c61df0376217/log/controller/logs/tempest_log.txt#40163 | |
| 18:20:55 | frickler | action() doesn't use request, but post() https://github.com/openstack/tempest/blob/04cb0adc822ffea6c7bfccce8fa08b03739894b7/tempest/lib/services/compute/servers_client.py#L218-L233 | |
| 18:20:58 | gmann | and output is empty {"output": "" - https://zuul.opendev.org/t/openstack/build/9890c9b53059410eabc0c61df0376217/log/controller/logs/tempest_log.txt#40167 | |
| 18:20:59 | sean-k-mooney | gmann: no melwitt found where we convert it | |
| 18:21:15 | sean-k-mooney | in the api log and in the debug of osc its a 404 | |
| 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 | |