Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2018-07-27
19:16:36 melwitt yeah, I mean how do we configure another library to log at a certain different level
19:16:36 dansmith I wonder if we've been doing this since this patch merged...
19:16:41 dansmith surely thought we'd have heard of it
19:18:05 dansmith there's a default log levels thing
19:18:53 sean-k-mooney well privsep has its own log handeler that redirects everything over the unix socket https://github.com/openstack/oslo.privsep/blob/master/oslo_privsep/daemon.py#L144
19:18:59 dansmith https://docs.openstack.org/kilo/config-reference/content/list-of-compute-config-options.html
19:19:09 dansmith default_log_levels =
19:19:42 dansmith default contains, for example: oslo.messaging=INFO
19:19:43 dansmith heh, that's kilo, but... :)
19:19:59 melwitt oh, never knew about that. cool
19:21:36 dansmith I don't see that we much control the execution of the daemon really,
19:21:43 dansmith so not sure if it even knows what our config is
19:22:25 dansmith or how it knows to have debug on
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 :p
20:21:22 mnaser dansmith: right, but yknow, not an instance from march lets say
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

Earlier   Later