| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2018-07-27 | |||
| 18:29:13 | dansmith | and I pushed up the other fixes to that, btw | |
| 18:29:24 | dansmith | since you hadn't and seemingly got distracted with this other thing | |
| 18:29:56 | dansmith | oh I see you did | |
| 18:29:57 | dansmith | cool | |
| 18:33:18 | mriedem | sure did | |
| 18:33:29 | openstackgerrit | Matt Riedemann proposed openstack/nova master: Add functional test for forced live migration rollback allocs https://review.openstack.org/586636 | |
| 18:35:21 | mriedem | well, just in time for us to kill the shared storage provider support, i got it passing the ceph job http://logs.openstack.org/63/586363/3/check/legacy-tempest-dsvm-full-devstack-plugin-ceph/569c574/ | |
| 18:36:50 | dansmith | presumably because we're left with broken allocations after a revert or something, but don't check/assert them? | |
| 18:37:22 | mriedem | right tempest won't assert any of that stuff, | |
| 18:37:41 | mriedem | we do have a post-test hook in the nova-next job for making sure there are no orphaned allocations but only on compute node providers | |
| 18:37:50 | dansmith | we had some sanity checking and logging in the RT when we removed the healing.. maybe there is some evidence in there? | |
| 18:38:47 | mriedem | oh nvm it's not just computes, it's all resource providers | |
| 18:38:51 | mriedem | but we don't run it on that job | |
| 18:39:13 | 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_17_31_35_337258 | |
| 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 | |