| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2023-07-27 | |||
| 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 | |
| 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 | |