| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2017-01-31 | |||
| 18:26:51 | sdague | but all this code is executed here - https://github.com/openstack-dev/grenade/blob/a1ea5cec068d59b9c2caa1c82d7ee2584d63aa08/grenade.sh#L283-L287 | |
| 18:27:14 | sdague | and I don't understand how code that runs after the failure in question is going to fix the issue | |
| 18:27:41 | dansmith | sdague: you mean it's on the old side? | |
| 18:27:47 | sdague | yes | |
| 18:28:08 | sdague | http://logs.openstack.org/79/396679/45/check/gate-grenade-dsvm-neutron-multinode-ubuntu-xenial/11607f2/logs/grenade.sh.txt.gz#_2017-01-30_09_49_58_107 | |
| 18:28:16 | dansmith | sdague: okay, I'm not sure how it's hitting that on the old side, since the thing that is failing merged on friday | |
| 18:28:26 | sdague | dansmith: well that's where this failure is | |
| 18:28:51 | dansmith | sdague: okay, so, I guess we'll continue to hold onto this fix for a condition that we know we've added | |
| 18:29:07 | dansmith | sdague: if you could tell me why you have a problem with it, it'd sure save us time when this becomes a critical problem | |
| 18:29:40 | dansmith | 'cause I still am confused about that part | |
| 18:30:15 | sdague | dansmith: because I don't see what it's making better. This was framed with the logs in question as fixing that issue, but they don't, because that's a different and real issue about initial node racing on the way up | |
| 18:30:57 | artom | Is http://logs.openstack.org/59/424759/12/gate/gate-tempest-dsvm-cells-ubuntu-xenial/d7b1311/console.html#_2017-01-31_17_48_34_663215 something to do with ongoing cells work? | |
| 18:30:58 | dansmith | sdague: you agree that race conditions exist that we know about, but just haven't hit yet right? | |
| 18:32:59 | sdague | dansmith: there are bunches of those though, and I'm fine fixing issues we're hitting. It just seems like this keeps getting pushed for issues we aren't yet hitting. And that are unlikely to hit based on the real timelines for additional stuff that happens before the second tempest run happens | |
| 18:33:58 | dansmith | sdague: right, so paraphrasing, what you just said is: "This is a race we know about, but right now we think we'll never hit it, so we'll just wait until the context has fallen out of our brains and it becomes a gate blocker in six months" | |
| 18:34:04 | dansmith | over ten lines of bash | |
| 18:34:36 | dansmith | sdague: and fwiw, the reason they're hitting that (just found out) is that their patch set base to master | |
| 18:34:51 | dansmith | hitting that in that way I mean | |
| 18:42:42 | melwitt | artom: not that I know of | |
| 18:43:38 | artom | melwitt, hrmm, thanks :) | |
| 18:47:35 | melwitt | artom: we recently merged a patch (on Jan 27) that might be related to this, so I'll do some digging through the logs to see what could be happening | |
| 18:48:38 | artom | melwitt, 4 days ago? We'd have noticed it by now if it was causing consistent failure in the gate... | |
| 18:48:48 | mriedem | i've seen that failure | |
| 18:48:52 | mriedem | it's intermittent | |
| 18:50:41 | melwitt | this is the test that uses reset-state to set servers to error, then lists them. there must be some race here | |
| 18:53:08 | jaypipes | cdent: any ideas on this? (I've updated my tox venv to the latest wsgi-intercept release): http://paste.openstack.org/show/597078/ | |
| 18:53:54 | jaypipes | cdent: lol, nm | |
| 18:54:12 | cdent | jaypipes: what was it? | |
| 18:54:32 | jaypipes | cdent: I'd forgotten to do: | |
| 18:54:39 | jaypipes | self.rt.report_client = self.report_client | |
| 18:54:51 | jaypipes | where self.report_client is the test_report_client.NoAuthKeystoneClient thing | |
| 18:55:01 | cdent | ah | |
| 18:55:05 | jaypipes | boom. | |
| 18:55:08 | jaypipes | perfecto. | |
| 18:55:13 | mriedem | artom: melwitt: http://tinyurl.com/hkpuoel | |
| 18:55:45 | cdent | jaypipes: cool, I was worried urllib3 had gone off and changed something (as they do) and made wsgi-intercept much more complicated (it's already a hairball) | |
| 18:55:50 | jroll | dansmith: did you get your question answered? typical devstack registers nodes with ironic after starting ironic, and then we (re)start n-cpu. so yeah, thinking we should wedge it in here-ish https://github.com/openstack/ironic/blob/master/devstack/lib/ironic#L1556 | |
| 18:55:57 | jaypipes | cdent: nah | |
| 18:56:49 | artom | mriedem, hrmm, does keep popping up, doesn't it? | |
| 18:57:37 | artom | And it predate's the change melwitt was talking about, since there are some on the 24th... | |
| 18:58:03 | melwitt | yeah, looks like this has been happening for awhile, just not often | |
| 19:00:46 | mriedem | i'll open a bug | |
| 19:01:17 | openstackgerrit | Pushkar Umaranikar proposed openstack/nova: Adopts keystoneauth with glance client. https://review.openstack.org/412634 | |
| 19:03:05 | artom | mriedem, melwitt, https://github.com/openstack/tempest/blob/master/tempest/api/compute/admin/test_servers.py#L50 | |
| 19:03:20 | artom | That seems... obvious? Surely you'd want to wait for the server to enter error state at that point... | |
| 19:06:26 | mriedem | artom: well it could, | |
| 19:06:57 | artom | I checked the api-ref, it returns 202, not 200 | |
| 19:06:58 | mriedem | it fails in cells v1, i assume, because the child cell is reporting the vm_state change back up to the parent api cell so the instances in both dbs are in sync, and when tempest makes the GET request, the api cell doesn't have the updated vm_state yet | |
| 19:07:12 | artom | So it's async and might not be done by the time the next requests lists the servers in error state... | |
| 19:08:07 | mriedem | it's actually odd that it's a 202 | |
| 19:08:35 | mriedem | because all that api does is literally change the vm_state in the db https://github.com/openstack/nova/blob/master/nova/api/openstack/compute/admin_actions.py#L82 | |
| 19:10:41 | mriedem | the upcall to the api cell is an rpc cast, | |
| 19:10:47 | mriedem | i wonder if that's why it's a 202, for cells v1 | |
| 19:13:40 | artom | Where does the cells call happen in that? | |
| 19:13:51 | mriedem | in nova.objects.Instance.save | |
| 19:14:35 | melwitt | I would think that would save it at the top and should be returned as 'error' as expected by the test. the save() would sync the vm_state change to the child. the get_all in compute/api is reading from child cells, so that's probably how it's happening | |
| 19:15:13 | melwitt | we've put in some conditionals "if cells v1, read from the top" but it looks like this was missed, for the get_all | |
| 19:15:20 | artom | Bah, vim ctags has failed me | |
| 19:15:34 | artom | It took me to agents.py save method for some reason | |
| 19:16:04 | openstack | Launchpad bug 1660747 in OpenStack Compute (nova) "test_list_servers_filter_by_error_status intermittently fails with MismatchError on no servers in response" [Medium,Confirmed] | |
| 19:16:04 | mriedem | here is the bug btw https://bugs.launchpad.net/nova/+bug/1660747 | |
| 19:16:25 | melwitt | thanks | |
| 19:16:38 | openstackgerrit | Lee Yarwood proposed openstack/nova: WIP - libvirt: Remove redundant bdm serial mangling during swap_volume https://review.openstack.org/427364 | |
| 19:17:15 | mriedem | sfinucan: do you know the ReST magic to find the root of a doc tree? | |
| 19:17:19 | mriedem | for a link | |
| 19:18:25 | artom | melwitt, you wanna propose a fix to Tempest? Shall I? | |
| 19:18:53 | dansmith | melwitt: I definitely had that in one of my patches at some point | |
| 19:19:03 | melwitt | artom: I'll propose a fix to nova, it's the get_all that needs a tweak I think | |
| 19:19:15 | dansmith | melwitt: for get_all, but I don't see it right now, so might've been the victim of a rebase, although I was failing the cells job regularly without it | |
| 19:19:34 | artom | melwitt, aha! | |
| 19:19:35 | melwitt | dansmith: yeah, I think it must have gotten lost in the mix | |
| 19:19:56 | artom | I still think Tempest should wait after a request that returns a 202, not just assume it's been completed... | |
| 19:20:04 | openstackgerrit | Eric Fried proposed openstack/nova: Introduce base PowerVM driver https://review.openstack.org/391288 | |
| 19:20:22 | openstackgerrit | Sarafraj Singh proposed openstack/nova-specs: Send service token along with user tokens https://review.openstack.org/426933 | |
| 19:20:26 | mriedem | melwitt: technically, we don't have to care about fixing latent bugs in cells v1 | |
| 19:21:08 | dansmith | mriedem: this isn't latent | |
| 19:21:10 | melwitt | mriedem: it's not a latent bug in cells v1. it should have been working fine until we added cells v2 instance listing from all cells | |
| 19:22:59 | openstackgerrit | Matt Riedemann proposed openstack/nova: doc: add upgrade notes to the placement devref https://review.openstack.org/427367 | |
| 19:23:01 | mriedem | cdent: bauzas: ^ | |
| 19:23:11 | mriedem | dansmith: melwitt: ok | |
| 19:24:02 | browne | mriedem: do the RPC versions need to be updated for Ocata? seemed so, so i put up this patch: https://review.openstack.org/#/c/425958/ | |
| 19:24:36 | lyarwood | dansmith: https://review.openstack.org/#/c/427267 should be ready for a review if you have time later today | |
| 19:25:06 | melwitt | artom: I think we've left the test alone since it helps catch our bugs, but technically you're right, a 202 means wait | |
| 19:26:03 | artom | melwitt, well, is the problem that the server state update takes too long, or doesn't happen at all? Because the latter isn't affected by waiting | |
| 19:26:22 | mriedem | it would have to be a race, | |
| 19:26:26 | mriedem | else this would be 100% failure | |
| 19:26:35 | melwitt | artom: the problem is our code is reading instances from the child cells instead of the parent cell, for cells v1 | |
| 19:26:40 | artom | It'll still catch the bugs, except it'll do it by timing out on the wait_for_server_status call | |
| 19:27:10 | melwitt | most of the time, the sync down gets to the child before our read does, and in that case, it will pass the test | |
| 19:27:23 | melwitt | no, it wouldn't catch this bug I don't think | |
| 19:27:45 | melwitt | this is like a split second difference | |
| 19:28:29 | artom | Ah, so the status ends up being synced in all cases | |
| 19:28:36 | melwitt | yes | |
| 19:28:39 | mriedem | lyarwood: i threw the rc-potential tag on that one since it's a regression | |
| 19:29:03 | lyarwood | mriedem: ack thanks | |
| 19:29:23 | artom | melwitt, wait, just to make this clear in my head: the write happens on the parent cell, the read from the child cells, so if you time your read really quickly after the write, you won't get the new state? | |
| 19:29:42 | artom | And the fix you have in mind is to read from the parent cell? | |
| 19:30:05 | melwitt | yes. cells v1 normally reads from the parent cell. it has instances table in the parent and the childs and it syncs them | |
| 19:31:32 | artom | Hrmpf, this is indeed a case of a test being technically wrong but actually useful | |
| 19:31:47 | dansmith | artom: no | |