| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2023-07-27 | |||
| 17:55:37 | frickler | you can add --debug to the osc call to verify the body | |
| 17:55:47 | melwitt | uh wtf self.assertTrue(output, "Console output was empty.") | |
| 17:55:50 | sean-k-mooney | no self.assertTrue takes an object to test and a message to return if it fails | |
| 17:55:56 | dansmith | melwitt: yeah I wonder if that means "doesn't fail" | |
| 17:56:08 | melwitt | this is asserting the exact opposite of what the docstring says | |
| 17:56:12 | dansmith | sean-k-mooney: ahhh, right okay | |
| 17:56:19 | dansmith | not assertEqual | |
| 17:56:29 | melwitt | ohh ok right | |
| 17:56:30 | dansmith | confusing | |
| 17:56:32 | sean-k-mooney | right | |
| 17:56:42 | sean-k-mooney | they shoudl not be useing assertTrue relaly in this case | |
| 17:56:48 | dansmith | yeah for serious | |
| 17:56:56 | sean-k-mooney | as i said they are relying on the boolean convertion to true of a non empty string | |
| 17:57:07 | melwitt | yeah bc they're saying "I got an error string, it must be a console!" | |
| 17:57:28 | sean-k-mooney | right so the fact this is failing | |
| 17:57:39 | sean-k-mooney | is telliing me the 404 had an emptyp body | |
| 17:57:48 | sean-k-mooney | im going to get the request id and check the api log | |
| 17:57:54 | dansmith | I wish frickler wasn't here watching this circus of three seasoned nova cores trying to figure out how one of the most basic calls works :/ | |
| 17:57:57 | sean-k-mooney | it should have the content lenght | |
| 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 | 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}} | |
| 17:59:49 | melwitt | this means not an empty string no? | |
| 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 | self.assertEqual(lines, 3) | |
| 18:04:40 | melwitt | lines = len(output.split('\n')) | |
| 18:04:40 | melwitt | I don't get how this is passing though | |
| 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 | |