| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2018-07-27 | |||
| 23:30:18 | melwitt | finally \o/ | |
| 23:49:23 | mnaser | well i know its late | |
| 23:49:29 | mnaser | but now even another whole interesting failure | |
| 23:49:39 | mnaser | no record in nova_api but one in the cell | |
| 23:49:40 | mnaser | lol | |
| 23:54:59 | melwitt | mnaser: no build request or instance mapping? | |
| 23:55:30 | mnaser | melwitt: build request, no instance mapping | |
| 23:55:53 | mnaser | wait sorry | |
| 23:55:57 | mnaser | it doesnt exist in the cell, sorry | |
| 23:56:00 | melwitt | build request, instance in cell, no instance mapping | |
| 23:56:02 | melwitt | build request only? | |
| 23:56:04 | mnaser | yes | |
| 23:56:08 | mnaser | build request only | |
| 23:56:14 | melwitt | that's the exact same thing rdo cloud ran into | |
| 23:56:30 | mnaser | so shows up in list but not deletable etc | |
| 23:56:34 | melwitt | right | |
| 23:56:45 | mnaser | i guess i can just delete the build request and have it disappear? | |
| 23:56:50 | melwitt | do you have several or just a few? like does it happen a lot? | |
| 23:57:01 | melwitt | yes, that's what I told rdo cloud to do too | |
| 23:57:11 | mnaser | i mean after running my fixup script, i still had a few instances that were stuck BUILD/scheduling | |
| 23:57:38 | melwitt | I dug around in the code and didn't see a way it can happen other than nova-api going down at the precise moment between the build_request.create() and the instance_mapping.create() or the instance_mapping.create() somehow failing | |
| 23:57:58 | mnaser | so for context it is possible that rpc and/or db both had issues at the time | |
| 23:58:05 | mnaser | does the build request and instance_mapping get created at the same time or? | |
| 23:58:08 | melwitt | which seems it would be crazy rare ... so maybe we're missing some other way it could happen | |
| 23:58:15 | melwitt | pretty much yeah. let me grab a link | |
| 23:58:49 | melwitt | https://github.com/openstack/nova/blob/3e0b17b1e138615b66293976ca5b55c291957844/nova/compute/api.py#L930-L942 | |
| 23:59:15 | melwitt | yeah, soon you can come fix all these bugs | |
| 23:59:18 | mnaser | ok that's interesting | |
| 23:59:18 | mnaser | haha | |
| 23:59:59 | mnaser | so build request was created, instance mapping was *not* created. unless there was an attempt to delete the instance while it was still in build request | |
| #openstack-nova - 2018-07-28 | |||
| 00:00:05 | melwitt | yeah so, just wonder if there's some bizarre way a delete could miss the build request, similar to what mriedem was saying earlier for the bug we discussed earlier | |
| 00:00:34 | mnaser | i might be like 5 steps behind your discussion so i might just be echoing stuff y'all already discusssed :p | |
| 00:00:48 | melwitt | nah | |
| 00:01:14 | melwitt | it's more likely that somehow a delete was partial | |
| 00:01:31 | melwitt | but I didn't find how last time I went spelunking in the code | |
| 00:02:17 | melwitt | (the nah was, no, you're not echoing) | |
| 00:02:22 | mnaser | :p | |
| 00:02:42 | mnaser | im looking in nova/conductor/manager.py on how ending up with a build request but without instance_mapping | |
| 00:08:16 | melwitt | build request is deleted once scheduled, so that means it had to be during the create process somewhere. ignore what I was saying about delete (unless it's a delete while booting? but I didn't see a way there either) | |
| 00:12:43 | mnaser | melwitt: does instance.delete() get rid of the mapping? | |
| 00:12:46 | mnaser | or does the mapping stay forever | |
| 00:13:06 | melwitt | mapping stays until you 'nova-manage db archive_deleted_rows' | |
| 00:13:20 | mnaser | and we dont do that | |
| 00:13:20 | mnaser | hmm | |
| 00:13:23 | melwitt | as of rocky, I believe | |
| 00:13:40 | mnaser | cause i went through the code and i couldn't find any instances where the instance mapping doesnt get deleted *after* the build request | |
| 00:13:49 | mnaser | in nova/compute/api.py and nova/conductor/manager.py | |
| 00:13:53 | mnaser | not sure if there is any other places to look | |
| 00:13:53 | melwitt | yeah, same | |
| 00:17:07 | mnaser | it would be good to know if the InstanceMapping was created and deleted or just never created in the first place | |
| 00:17:11 | mnaser | dont think there is an easy way to know that | |
| 00:17:14 | mnaser | let me try to look at logs | |
| 00:25:39 | mnaser | melwitt: looks like a db server issue just a few seconds after the build request was created | |
| 00:26:04 | melwitt | interesting. so possible that the instance mapping INSERT failed? | |
| 00:26:20 | mnaser | let me look at the stack traces of the failures | |
| 00:26:21 | melwitt | I mean, if it's really a few seconds, that would be too long after | |
| 00:26:26 | mnaser | hopefully it shows where | |
| 00:27:59 | mnaser | melwitt: AHA | |
| 00:28:06 | mnaser | stacktrace in db fail | |
| 00:28:06 | mnaser | inst_mapping.create() | |
| 00:28:12 | melwitt | holy crap | |
| 00:28:24 | mnaser | and looks like in the exception handling | |
| 00:28:27 | mnaser | it does self._cleanup_build_artifacts(None, instances_to_build) | |
| 00:28:58 | mnaser | so if a create failed, we do _cleanup_build_artifacts but maybe we need to make sure that we assume things don't exist in _cleanup_build_artifacts | |
| 00:29:02 | melwitt | and that *didn't* delete the build request? another db trace? | |
| 00:29:07 | melwitt | we do | |
| 00:29:17 | mnaser | well i assume the exception handling failed too | |
| 00:29:21 | mnaser | because the db was out | |
| 00:29:26 | melwitt | oh, yeah ok | |
| 00:29:28 | mnaser | let me share the stack trace | |
| 00:30:08 | mnaser | http://paste.openstack.org/show/726772/ | |
| 00:30:13 | melwitt | this is wild. I really didn't think it was going to be that the create() failed due to db issues | |
| 00:30:34 | mnaser | is there a transactional system in nova.objects? | |
| 00:30:50 | mnaser | like maybe we can actually make the create build request and instance mapping a single transaction with commit | |
| 00:31:15 | melwitt | I've had it on my todo list to write a functional test that raises during the instance_mapping.create() to repro the bug, and to show how the orphan build request can't be deleted | |
| 00:31:39 | mnaser | it would still fail but at least the build request wouldn't be there anymore | |
| 00:31:59 | melwitt | hm ... we could if we create a new method that does them both under the same oslo.db session decorator thing, I believe | |
| 00:32:09 | mnaser | i guess this http request should have returned 500 | |
| 00:32:13 | melwitt | to make it be one transaction | |
| 00:32:16 | mnaser | so its not like the instance disappears under the user too | |
| 00:32:35 | mnaser | "HTTP exception thrown: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible." yup | |
| 00:32:54 | melwitt | very interesting. this data is gold | |
| 00:32:57 | mnaser | melwitt: is there any example of somewhere where this happens? i can write a test with failure of instance_mapping.create() and then make it in a single transaction | |
| 00:33:04 | mnaser | this == single transaction | |
| 00:33:11 | melwitt | oh, lemme see | |
| 00:33:58 | mnaser | i should find other places where the db writes had failed and find their stack traces | |
| 00:34:03 | mnaser | ill do that too | |
| 00:37:18 | melwitt | there are some things in here https://github.com/openstack/nova/blob/master/nova/api/openstack/placement/objects/resource_provider.py | |
| 00:37:46 | melwitt | specifically this one https://github.com/openstack/nova/blob/master/nova/api/openstack/placement/objects/resource_provider.py#L4039 | |
| 00:38:06 | melwitt | the note there explains it well | |
| 00:40:12 | melwitt | awesome mnaser, thanks | |
| 00:47:58 | mnaser | ok i got a gold mine | |
| 00:48:23 | mnaser | i retrieved a list of all the .save or .create that failed because of db errors | |
| 00:48:34 | mnaser | which should be useful to group up together into a single transaction | |
| 00:48:56 | mnaser | im just deduping the list | |
| 00:49:06 | mnaser | fwiw -- grep _handle_dbapi_exception /var/log/nova/nova-api-wsgi.log -B70 | egrep 'nova.api.openstack.wsgi .*\.(save|create)' -B1 | |
| 00:50:42 | melwitt | sweet | |
| 00:54:51 | melwitt | mnaser: do you want to write up a bug for this and include the trace paste and all? else I can do it later, I have to run soon | |
| 00:55:23 | mnaser | melwitt: https://bugs.launchpad.net/nova/+bug/1784074 i added them all here | |
| 00:55:23 | openstack | Launchpad bug 1784074 in OpenStack Compute (nova) "Instances end up with no cell assigned in instance_mappings" [Medium,In progress] - Assigned to Matt Riedemann (mriedem) | |