Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2018-07-27
19:22:57 dansmith but yeah, if it's being fed into our logger (like sean-k-mooney is suggesting) then setting a level in that config might affect it
19:23:38 melwitt hm, yeah. the example shows all kinds of libraries that aren't openstack things as being affected
19:23:42 sean-k-mooney well this is what is handeling the log message on the nova side of the call https://github.com/openstack/oslo.privsep/blob/master/oslo_privsep/daemon.py#L206
19:24:25 dansmith melwitt: it has nothing to do with openstack
19:24:36 dansmith melwitt: it's in our config of the root logger,
19:24:45 dansmith which any library will ultimately use
19:24:55 dansmith it just matters that it's in our process space
19:25:37 dansmith so the daemon being outside, would be unaffected (unless it's looking at our config), but if it's redirecting all the log traffic over the channel and we have something our side reading that and logging _as_ privsep.daemon in our process,
19:25:45 dansmith then our root logger config would affect it
19:25:53 melwitt okay, I see. thanks for explaining that
19:26:05 sean-k-mooney dansmith: in this case it even going to work across process because both the root wrap and fork clients swap out the looger to redirect it over the socket
19:26:21 dansmith sean-k-mooney: yeah I just said that :)
19:27:06 mriedem so we just need to hard-code oslo.privsep=INFO or something in our default_log_levels yeah for that bug? didn't read all the backscroll
19:27:16 sean-k-mooney hah yep. i was typeing when you did :)
19:27:23 dansmith sean-k-mooney: heh okay
19:27:29 dansmith mriedem: yeah, sounds like it
19:27:34 mriedem easy peasy
19:27:37 dansmith yup
19:28:02 mriedem melwitt: don't forget to defer a bunch of these https://blueprints.launchpad.net/nova/rocky
19:28:21 melwitt mriedem: right, thanks
19:28:24 mriedem i only see 3 in there that wouldn't be deferred
19:28:33 mriedem mox-removal, versioned notifications and stephen's numa vswitch bp
19:28:54 melwitt thanks
19:29:09 sean-k-mooney dansmith: am could we use a decoreator/context manager to also chagne the config for spcific call?
19:29:49 dansmith sean-k-mooney: not sure I parsed that, but I think we'd not want to override log levels in a context manager
19:30:43 sean-k-mooney basically im thinking about your previous suggstion of a decorator for this is sensitive never logit cases
19:30:59 dansmith sean-k-mooney: yep, something intentional for this might be good
19:31:30 melwitt setting the default log level for oslo.privsep is a good mitigation we can do immediately. then we can look at the idea of adding something to oslo.privsep to control this in a better, non-overrideable way (though I guess one could argue if the user really wants to override, they should be able to)
19:31:38 sean-k-mooney the default log level change is also good but that read tty call proablly should never be logged
19:32:20 sean-k-mooney melwitt: if the user really want to log it that much they could add a print()
19:32:39 sean-k-mooney or remvoe the decorator
19:32:57 sean-k-mooney its likely that you would only want to do this if your debugging
19:33:26 melwitt yeah, I just meant to point out it's a consideration. not arguing either way
19:36:13 sean-k-mooney ya thats true
19:36:46 mriedem the default_log_levels things is backportable, which i'm assuming this needs to be
19:36:49 mriedem we've had privsep in for awhile
19:37:15 dansmith I've been trying to git-review this mofo for a few minutes now
19:38:04 sean-k-mooney well the default_log_levels can be set in deployment tools so it can be done downstream also even if it was not upstream
19:38:45 openstackgerrit Dan Smith proposed openstack/nova master: Force oslo.privsep.daemon logging to INFO level https://review.openstack.org/586643
19:38:50 dansmith thar ^
19:39:40 dansmith we can check the logs after a run of that and make sure theres no privsep debug noise in there
19:51:22 sean-k-mooney dansmith: the only down side to this change is i used to use some of those log messages to debug os-vif plugging stuff but in heighsight i should have proably questioned why they were there
19:51:28 sean-k-mooney dansmith: that said 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_229614
19:51:44 dansmith sean-k-mooney: this is just the default, you can still override it in config to turn it on
19:52:01 sean-k-mooney this is being loged form the privsep deamon but reported as oslo_concurrency
19:52:28 sean-k-mooney dansmith: oh i know, what will we do in the gate?
19:53:12 dansmith well, we can override this for the gate, it just needs to not be on by default
19:54:06 dansmith sean-k-mooney: are you sure? that doesn't look like the privsep format
19:54:18 dansmith and processutils would log something like that
19:54:39 dansmith maybe it's inside the daemon, but running processutils, which is emitting the actual log?
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

Earlier   Later