| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2018-07-27 | |||
| 18:40:23 | mriedem | yeah i don't see any obvious warnings related to allocatoins | |
| 18:40:52 | mriedem | i think if we ran our post-test leaked allocation hook on this job it would fail | |
| 18:41:11 | mriedem | well, maybe not for single node | |
| 18:42:56 | dansmith | yeah, so there are 133 logs of instance fd563ed2-d42c-4dc1-a614-8700c6e6c8fd | |
| 18:43:06 | dansmith | having non-cleaned-up allocations | |
| 18:43:36 | dansmith | although really the allocations that we'd destroy wouldn't be against the compute node, | |
| 18:43:39 | dansmith | and would be gone not stale | |
| 18:43:43 | dansmith | so even your check probably wouldn't catch it | |
| 18:43:54 | dansmith | because we'd be _losing_ not _leaking_ disk allocations | |
| 18:45:15 | dansmith | also, um | |
| 18:45:25 | dansmith | I just noticed that we're logging an entire console log out of privsep somewhere | |
| 18:45:34 | dansmith | http://logs.openstack.org/63/586363/3/check/legacy-tempest-dsvm-full-devstack-plugin-ceph/569c574/logs/screen-n-cpu.txt.gz#_Jul_27_18_07_23_550670 | |
| 18:46:01 | dansmith | you could argue that is a security issue if instances log sensitive info to their console | |
| 18:46:31 | mriedem | nice, 9 of those | |
| 18:46:49 | mriedem | you can open that bug | |
| 18:47:47 | dansmith | okay | |
| 18:48:04 | dansmith | does privsep daemon log everything over the channel or something? | |
| 18:49:51 | sean-k-mooney | dansmith: that log is becasue seting a route in teh guest failed http://logs.openstack.org/63/586363/3/check/legacy-tempest-dsvm-full-devstack-plugin-ceph/569c574/logs/screen-n-cpu.txt.gz#_Jul_27_18_07_23_555618 | |
| 18:50:31 | dansmith | not sure about that | |
| 18:50:32 | sean-k-mooney | i think | |
| 18:50:48 | Sundar_ | efried: I need to take off for lunch. I'll look for your response in https://review.openstack.org/#/c/577438/. We need to get this discussion to a closure. | |
| 18:50:49 | dansmith | don't think so, I'm not sure why we'd log the console output in that case | |
| 18:51:04 | dansmith | the route errors on the console are just there because we're logging it, if that's what you're looking at | |
| 18:51:51 | sean-k-mooney | yes it was but this looks like the ouput for dmesg when we are unning through cloud-init | |
| 18:52:05 | sean-k-mooney | well i gess its the main console log | |
| 18:53:10 | dansmith | sean-k-mooney: it's the instance console log | |
| 18:53:16 | dansmith | which is more than dmesg | |
| 18:54:06 | sean-k-mooney | well its a debug log. i wonder is it related to http://logs.openstack.org/63/586363/3/check/legacy-tempest-dsvm-full-devstack-plugin-ceph/569c574/logs/screen-n-cpu.txt.gz#_Jul_27_18_07_23_548723 | |
| 18:54:53 | dansmith | it looks to me like privsep daemon is logging anything sent over the channel, | |
| 18:54:55 | sean-k-mooney | by that i mean its a debug log so at least it does not do this normally | |
| 18:55:03 | dansmith | and since we're using it to do a readpty of the console, it gets logged | |
| 18:55:16 | dansmith | sean-k-mooney: lots of people run with debug on all the time | |
| 18:55:33 | openstack | Launchpad bug 1784062 in OpenStack Compute (nova) "Instance console data is logged at DEBUG" [Undecided,New] | |
| 18:55:33 | dansmith | https://bugs.launchpad.net/nova/+bug/1784062 | |
| 18:55:34 | dansmith | melwitt: ^ | |
| 18:55:48 | dansmith | I dunno what will be involved in squelching that, | |
| 18:55:57 | dansmith | but might be good to fix that before GA, IMHO | |
| 18:55:59 | melwitt | gah, moar bugs | |
| 18:56:42 | melwitt | yeah, agreed. I'll put it on the RC1 list | |
| 18:57:06 | sean-k-mooney | dansmith: well i know privsep propagate any excpetions back over the unix socket and any loging within the privesep deamon is redirected to the parrent too as far as i know | |
| 18:57:18 | dansmith | I'd like to point to mriedem's statement that we should be finding and fixing critical bugs during this phase instead of rushing on a lot of FFEs | |
| 18:57:26 | dansmith | the last 24 hours has been pretty ... that. | |
| 19:01:20 | mriedem | SWEET VALIDATION | |
| 19:02:52 | sean-k-mooney | dansmith: its coming from this line https://github.com/openstack/oslo.privsep/blob/master/oslo_privsep/daemon.py#L442 | |
| 19:03:18 | dansmith | sean-k-mooney: that wouldn't make much sense | |
| 19:03:26 | dansmith | I expect it's the one below, L455 | |
| 19:03:41 | dansmith | TestNetworkBasicOps-1426085565] privsep: reply[140593546325360]: (4, '') | |
| 19:03:48 | sean-k-mooney | sorry yes l455 | |
| 19:03:54 | dansmith | yup | |
| 19:04:26 | melwitt | that doesn't look very squelchable | |
| 19:04:27 | sean-k-mooney | so should we just delete those? | |
| 19:04:53 | dansmith | melwitt: agree, it's sticky, but .. imagine what else we might be logging when we're running commands as root... | |
| 19:05:12 | melwitt | no, I agree. just thinking, how can we stop it | |
| 19:05:13 | dansmith | melwitt: maybe we recommend squelching privsep DEBUG logs in the levels as a security measure? | |
| 19:05:17 | dansmith | but still, | |
| 19:05:29 | dansmith | something better likely needs doing | |
| 19:05:30 | sean-k-mooney | we could add a conf option for extra verbose loggin to privsep. | |
| 19:05:53 | dansmith | we control that to some degree in our default levels for libraries, | |
| 19:06:04 | dansmith | assuming the daemon starts with our config | |
| 19:06:47 | sean-k-mooney | things like os-vif plugins create there own privsep deamons | |
| 19:07:05 | sean-k-mooney | it would be nice to turn that off by defaut globally | |
| 19:11:29 | dansmith | decorating privsep methods as "may return sensitive stuff" would be one way, and let the daemon just not log the result | |
| 19:11:44 | dansmith | for the DoS case, limiting what we log to 256 chars max or something seems prudent | |
| 19:12:46 | melwitt | are you talking about changes to oslo_privsep or nova? | |
| 19:12:57 | dansmith | well, the decoration would be both | |
| 19:13:09 | dansmith | we'd decorate our things, and the daemon code would have to honor it | |
| 19:13:17 | melwitt | okay, I see | |
| 19:13:25 | dansmith | the log length limit would be purely privsep | |
| 19:13:33 | melwitt | gotcha | |
| 19:13:45 | dansmith | and our forcing of a log level for our own daemon could maybe be all on our end, but not sure | |
| 19:14:44 | melwitt | yeah, I was looking for where the default log levels come from and didn't find it yet | |
| 19:15:03 | dansmith | well, we control them for our libraries you know, | |
| 19:15:14 | dansmith | but I think the daemon itself is logging this | |
| 19:15:16 | sean-k-mooney | melwitt: well this is a devstack run so we proably hardcode the loglevel to debug in the nova conf | |
| 19:15:20 | melwitt | the decorator idea sounds like a good feature but I don't know how hard it would be to coordinate that with oslo in the next week or so | |
| 19:15:21 | dansmith | but, I assumed it was following our debug=true, so.. | |
| 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 | |