| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2018-07-27 | |||
| 23:59:15 | melwitt | yeah, soon you can come fix all these bugs | |
| 23:59:18 | mnaser | haha | |
| 23:59:18 | mnaser | ok that's interesting | |
| 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 | hmm | |
| 00:13:20 | mnaser | and we dont do that | |
| 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 | melwitt | yeah, same | |
| 00:13:53 | mnaser | not sure if there is any other places to look | |
| 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 | inst_mapping.create() | |
| 00:28:06 | mnaser | stacktrace in db fail | |
| 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 | 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) | |
| 00:55:23 | mnaser | melwitt: https://bugs.launchpad.net/nova/+bug/1784074 i added them all here | |
| 00:56:05 | melwitt | okay | |
| 00:57:43 | melwitt | think I'm going to create a new bug since the db fail thing is a bit different | |
| 00:58:17 | mnaser | melwitt: it's up to you to how you see fit :) | |
| 00:58:26 | melwitt | :) | |
| 00:59:36 | mnaser | https://github.com/openstack/nova/blob/ff5cded9afa65cd4317ba0e3401692ed92c1d150/nova/api/openstack/placement/objects/project.py#L83-L92 | |
| 00:59:47 | mnaser | i think this is an easier pattern especially for create this stuff | |
| 00:59:53 | mnaser | rather than a top level function (i think) | |
| 01:00:27 | melwitt | yeah | |
| 01:01:13 | mnaser | https://github.com/openstack/nova/blob/16a2db6f23d150330dc82a56d0cf10366b004210/nova/objects/aggregate.py#L67-L78 | |
| 01:01:19 | mnaser | this seems like an interesting pattern too | |
| 01:01:26 | mnaser | im digging around code | |
| 01:02:34 | mnaser | im just curious/worry that wrapping things in the writer twice might break things | |
| 01:02:40 | mnaser | i.e.: https://github.com/openstack/nova/blob/16a2db6f23d150330dc82a56d0cf10366b004210/nova/objects/instance_mapping.py#L75-L86 | |
| 01:02:58 | melwitt | it will, don't nest it | |
| 01:03:00 | melwitt | well, | |
| 01:03:06 | melwitt | you can't nest a write under a read | |
| 01:03:23 | mnaser | can you nest two writes? or should i drop it from _create_in_db | |
| 01:03:33 | melwitt | so otherwise nesting is probably ok | |
| 01:03:43 | mnaser | ok cool | |
| 01:03:44 | melwitt | but I don't know if I've tried it, intentionally anyway | |
| 01:04:03 | mnaser | ill make sure i have a failing test first to make sure it actually gets fixed | |
| 01:05:58 | melwitt | awesome, sounds great | |
| 01:17:15 | openstack | Launchpad bug 1784093 in OpenStack Compute (nova) "Build requests can be orphaned without instance mappings" [Medium,Confirmed] - Assigned to Mohammed Naser (mnaser) | |
| 01:17:15 | melwitt | mnaser: https://bugs.launchpad.net/nova/+bug/1784093 fyi, I assigned it to you | |
| 01:18:22 | mnaser | melwitt: cool, i'm building up a test right now, i should probably have a patch later today if this doesnt end up much more complicated :> | |
| 01:19:12 | melwitt | okay, good luck. we'll take a look at it next week | |