| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2018-07-27 | |||
| 19:54:42 | sean-k-mooney | dansmith: that code is executed via privsep but that message is not from that log | |
| 19:54:52 | sean-k-mooney | dansmith: yes | |
| 19:55:17 | dansmith | okay I'm confused about what you're saying | |
| 19:55:33 | sean-k-mooney | sorry one sec | |
| 19:56:44 | sean-k-mooney | its basically this https://github.com/openstack/os-vif/blob/master/vif_plug_ovs/linux_net.py#L155 | |
| 19:56:55 | sean-k-mooney | which invokes processuitls here https://github.com/openstack/os-vif/blob/master/vif_plug_ovs/linux_net.py#L58 | |
| 19:58:18 | sean-k-mooney | the actull privsep request message is printed here http://logs.openstack.org/63/586363/3/check/legacy-tempest-dsvm-full-devstack-plugin-ceph/569c574/logs/screen-n-cpu.txt.gz#_Jul_27_17_31_34_229139 | |
| 19:59:21 | sean-k-mooney | but any loging privledge fucntions do is also relyed to the parent over the socket. | |
| 20:02:30 | sean-k-mooney | anyway lets see if that config option just effect the default log level of oslo.privspes own internal logging or also the suff call via a privsep context | |
| 20:03:16 | dansmith | okay, I'm still not sure what your concern is | |
| 20:03:23 | dansmith | but it's probably my friday brain | |
| 20:03:39 | openstackgerrit | Artom Lifshitz proposed openstack/nova master: DNM: Extra logs for volume detach device tags cleanup https://review.openstack.org/584032 | |
| 20:04:45 | sean-k-mooney | well im hoping that oslo.preivsep.deamon=INFO just disables the debug loggin for privsep debug logs but not debug logs from things called via privsep | |
| 20:05:19 | dansmith | why? | |
| 20:05:40 | dansmith | it should affect anything that logs with oslo.privsep.daemon, not anything else | |
| 20:06:05 | dansmith | if those concurrency logs are logged with a logger name of oslo.concurrency.processutils, then they should be unaffected | |
| 20:06:07 | dansmith | is that what you mean? | |
| 20:06:26 | sean-k-mooney | yes. | |
| 20:06:39 | dansmith | okay I think we'll be okay on that, assuming it works the way I think it does | |
| 20:06:45 | dansmith | I expect there is some code in privsep that does: | |
| 20:07:12 | dansmith | for message_logged_in_the_daemon: logger.getLogger(message.log_name).log.$level(message.msg) | |
| 20:07:42 | dansmith | so my change should only affect actual messages logged on the daemon log name | |
| 20:07:58 | dansmith | not anything logged in the context of the daemon at all | |
| 20:08:29 | dansmith | hmm, that code was kindof nonsense, let me try again: | |
| 20:08:33 | sean-k-mooney | its this code that i was unsure about https://github.com/openstack/oslo.privsep/blob/master/oslo_privsep/daemon.py#L249-L254 | |
| 20:08:38 | itlinux | hello Nova guys, when spinning up a VM, and the hypervisor is asking to pull the image from glance does that go over the storage network? thanks | |
| 20:09:08 | dansmith | sean-k-mooney: that's the daemon-side code that intercepts the logs to redirect | |
| 20:09:19 | sean-k-mooney | yes | |
| 20:09:22 | dansmith | it's the non-daemon code that does the actual logging and would do what I surmised above | |
| 20:09:30 | sean-k-mooney | well part of it | |
| 20:09:59 | sean-k-mooney | anyway we will see soon. | |
| 20:15:40 | dansmith | yup | |
| 20:19:40 | mnaser | there technically should never be rows with cell_id=NULL in instance_mappings.. right? | |
| 20:20:59 | dansmith | mnaser: mappings have no cell until they're scheduled | |
| 20:21:22 | mnaser | dansmith: right, but yknow, not an instance from march lets say | |
| 20:21:22 | mnaser | :p | |
| 20:21:23 | dansmith | they should always end up scheduled, to cell0 at least, but they can be there transiently and/or if something fails | |
| 20:22:41 | mnaser | alright so i think i'll have to write something to look in our cell vs cell0 and update mappings to make the db consistent | |
| 20:46:00 | mriedem | mnaser: same issue from last week right? | |
| 20:46:09 | mriedem | could have been rpc outage so a failed db update | |
| 20:46:13 | mriedem | er db? | |
| 20:46:24 | mriedem | failed write i mean | |
| 20:46:32 | mnaser | mriedem: no it looks like over the lifetime of our cloud any rpc or db related things might have accumulated a lot of things in nova_api with cell_id = NONE | |
| 20:46:36 | mnaser | like, 20000 worth. | |
| 20:46:51 | mriedem | i had also identified one spot in conductor where the build request will be gone and we don't set the instance mapping to cell0 | |
| 20:47:09 | mnaser | however for 99.9999% of those, they were actually assigned a cell and not buried in cell0 | |
| 20:47:52 | mnaser | dansmith, mriedem: http://paste.openstack.org/show/726767/ might be a useful little tool if someone ends up in the same situation | |
| 20:48:17 | mnaser | connect to api db, get all cells, go over them all and check where it can find the instance, and then print out an update statement for manual fix | |
| 20:48:29 | mriedem | we could nova-manage cell_v2 that baby | |
| 20:49:20 | mnaser | i can push up an initial patch but i dunno how much i can iterate/test/etc because i've been a bit overwhelmed | |
| 20:49:36 | mnaser | and it would have to be updated to use nova objects too i guess | |
| 20:49:40 | mriedem | np, or just report a bug and put this paste in it as a template | |
| 20:49:47 | mriedem | latter is fine ^ | |
| 20:49:52 | mnaser | good idea | |
| 20:50:15 | mriedem | is this finding instances in non-cell0 cells? | |
| 20:50:23 | mriedem | that aren't in error state? | |
| 20:50:58 | mnaser | mriedem: im not sure about the exact logic, but i grab a list of all cells, connect to them, and loop until i find an entry inside 'instances' table with the same id | |
| 20:51:02 | mnaser | if that is logically wrong, i can fix it | |
| 20:51:44 | mriedem | it makes sense | |
| 20:51:55 | mriedem | if the instance mapping doesn't tell what cell it's in, we have to iterate the cells looking for it | |
| 20:52:08 | mnaser | and there is no change it ever being in two cells | |
| 20:52:14 | mnaser | s/change/chance/ | |
| 20:52:18 | mriedem | is that a question? | |
| 20:52:22 | mnaser | yes | |
| 20:52:26 | mriedem | shouldn't be no | |
| 20:52:33 | mnaser | okay sounds good, because i break off once i find it and stop looping | |
| 20:52:35 | mriedem | but this shouldn't be happening in the first place | |
| 20:52:51 | mnaser | yeah :\ but i dunno how much to blame nova when it might have been an infra problem | |
| 20:53:14 | mriedem | i mean in a normal case we create the instance in the cell here https://github.com/openstack/nova/blob/6be7f7248fb1c2bbb890a0a48a424e205e173c9c/nova/conductor/manager.py#L1257 | |
| 20:53:54 | mriedem | if the user goes over quota we should put the instance into error state and mark the instance mapping https://github.com/openstack/nova/blob/6be7f7248fb1c2bbb890a0a48a424e205e173c9c/nova/conductor/manager.py#L1370 | |
| 20:54:34 | mriedem | in a normal case, we update the instance mapping here https://github.com/openstack/nova/blob/6be7f7248fb1c2bbb890a0a48a424e205e173c9c/nova/conductor/manager.py#L1322 | |
| 20:54:45 | mnaser | in any case -- https://bugs.launchpad.net/nova/+bug/1784074 | |
| 20:54:45 | openstack | Launchpad bug 1784074 in OpenStack Compute (nova) "Instances end up with no cell assigned in instance_mappings" [Undecided,New] | |
| 20:54:45 | mriedem | before deleting the build request and casting to compute | |
| 20:54:52 | mnaser | hmm | |
| 20:54:57 | mnaser | i wonder if i wanna update that script | |
| 20:55:00 | mnaser | to check if a build_request exists | |
| 20:55:05 | mriedem | if anything fails in between there we could fail to update the mapping | |
| 20:55:30 | mriedem | mnaser: maybe - if the build request exists, the instance shouldn't be in a cell | |
| 20:55:49 | mriedem | so L42 in your script is where i'd look for a build request | |
| 20:55:51 | mriedem | as a sanity check | |
| 20:56:24 | mnaser | mriedem: yeah i was planning to just run the mysql till a certain point and assume the rest was just unscheduled stuff but it could be confusing to hand off to others | |
| 20:57:10 | mnaser | i'm feeling to check if a build request exists at L27 so a) i dont hit the cells and b) if a build requests exists, technically there shouldn't be an issue because api calls will interact with that build request | |
| 20:57:24 | mnaser | i think the problem is there when a build request AND cell mapping is missing | |
| 20:57:44 | mnaser | but i believe if build request is there but cell mapping is missing, it'll work just fine and not do any weird 404s on instances | |
| 20:57:49 | mriedem | correct | |
| 20:58:07 | mriedem | this was the case i was worried about last week https://github.com/openstack/nova/blob/6be7f7248fb1c2bbb890a0a48a424e205e173c9c/nova/conductor/manager.py#L1243 | |
| 20:58:23 | mriedem | in that case, the api has deleted the build request, and we haven't updated the instance mapping | |
| 20:58:56 | mriedem | but, we wouldn't put the instance in cell0 b/c the user deleted the instance before we created it (via build request) | |
| 20:59:04 | mriedem | mnaser: might be nice info to know if these unmapped instances are deleted | |
| 20:59:15 | melwitt | one thing that's interesting that I learned recently is that if, for some reason, there is a case where a build request exists but *no* instance mapping exists, the API does not handle it in that, the "instance" will show up in a 'nova list' but it can't be deleted because delete will raise NotFound | |
| 20:59:46 | mriedem | i don't know how that could happen | |
| 20:59:56 | mriedem | we create the build request and the instance mapping in _provision_instances | |
| 21:00:00 | mriedem | *and request spec | |
| 21:00:18 | melwitt | and via code inspection, I don't know how that state could be gotten into other than nova-api restarting at precisely the moment after the build request is created but before the instance mapping was | |
| 21:00:34 | mriedem | https://github.com/openstack/nova/blob/6be7f7248fb1c2bbb890a0a48a424e205e173c9c/nova/compute/api.py#L930 and then https://github.com/openstack/nova/blob/6be7f7248fb1c2bbb890a0a48a424e205e173c9c/nova/compute/api.py#L942 | |
| 21:00:58 | mnaser | melwitt: yeah that's essentially the state that these vms are in | |
| 21:00:58 | mriedem | or the db failing the instance mapping insert | |
| 21:01:17 | melwitt | mnaser: I thought you had instance mappings though, right? | |
| 21:01:20 | melwitt | yeah, or that | |