Allow finer grained log levels

Currently all privsep calls use the same logging level as they use the
``oslo_privsep.daemon`` logger.

This creates a problem for services like nova where we don't want to
log its own privsep debug messages by default (even in debug mode) but
we want them for os-brick privsep calls.

This patch introduces a new string parameter to ``PrivContext`` called
``logger_name`` to control the name of the logger to use, which defaults
to ``oslo_privsep.daemon``.

Related-Bug: #1922052
Change-Id: Ie7cc25ed53563dd500f7b10ff43a48518d46a2e0
This commit is contained in:
Gorka Eguileor 2021-03-30 18:59:18 +02:00
parent 051476b84c
commit 71c732c833
4 changed files with 79 additions and 19 deletions

View File

@ -193,7 +193,8 @@ class PrivsepLogHandler(pylogging.Handler):
class _ClientChannel(comm.ClientChannel):
"""Our protocol, layered on the basic primitives in comm.ClientChannel"""
def __init__(self, sock):
def __init__(self, sock, context):
self.log = logging.getLogger(context.conf.logger_name)
super(_ClientChannel, self).__init__(sock)
self.exchange_ping()
@ -203,11 +204,12 @@ class _ClientChannel(comm.ClientChannel):
reply = self.send_recv((Message.PING.value,))
success = reply[0] == Message.PONG
except Exception as e:
LOG.exception('Error while sending initial PING to privsep: %s', e)
self.log.exception('Error while sending initial PING to privsep: '
'%s', e)
success = False
if not success:
msg = _('Privsep daemon failed to start')
LOG.critical(msg)
self.log.critical(msg)
raise FailedToDropPrivileges(msg)
def remote_call(self, name, args, kwargs):
@ -231,11 +233,11 @@ class _ClientChannel(comm.ClientChannel):
message = {encodeutils.safe_decode(k): v
for k, v in msg[1].items()}
record = pylogging.makeLogRecord(message)
if LOG.isEnabledFor(record.levelno):
LOG.logger.handle(record)
if self.log.isEnabledFor(record.levelno):
self.log.logger.handle(record)
else:
LOG.warning('Ignoring unexpected OOB message from privileged '
'process: %r', msg)
self.log.warning('Ignoring unexpected OOB message from privileged '
'process: %r', msg)
def fdopen(fd, *args, **kwargs):
@ -330,7 +332,7 @@ class ForkingClientChannel(_ClientChannel):
# parent
sock_b.close()
super(ForkingClientChannel, self).__init__(sock_a)
super(ForkingClientChannel, self).__init__(sock_a, context)
class RootwrapClientChannel(_ClientChannel):
@ -380,7 +382,7 @@ class RootwrapClientChannel(_ClientChannel):
raise
os.rmdir(tmpdir)
super(RootwrapClientChannel, self).__init__(sock)
super(RootwrapClientChannel, self).__init__(sock, context)
class Daemon(object):

View File

@ -65,6 +65,10 @@ OPTS = [
'recreate the current configuration. '
'This command must accept suitable --privsep_context '
'and --privsep_sock_path arguments.')),
cfg.StrOpt('logger_name',
help=_('Logger name to use for this privsep context. By '
'default all contexts log with oslo_privsep.daemon.'),
default='oslo_privsep.daemon'),
]
_ENTRYPOINT_ATTR = 'privsep_entrypoint'
@ -124,7 +128,7 @@ def init(root_helper=None):
class PrivContext(object):
def __init__(self, prefix, cfg_section='privsep', pypath=None,
capabilities=None):
capabilities=None, logger_name='oslo_privsep.daemon'):
# Note that capabilities=[] means retaining no capabilities
# and leaves even uid=0 with no powers except being able to
@ -150,6 +154,8 @@ class PrivContext(object):
cfg.CONF.register_opts(OPTS, group=cfg_section)
cfg.CONF.set_default('capabilities', group=cfg_section,
default=capabilities)
cfg.CONF.set_default('logger_name', group=cfg_section,
default=logger_name)
@property
def conf(self):

View File

@ -45,6 +45,20 @@ class TestException(Exception):
pass
def get_fake_context(conf_attrs=None, **context_attrs):
conf_attrs = conf_attrs or {}
context = mock.NonCallableMock()
context.conf.user = 42
context.conf.group = 84
context.conf.thread_pool_size = 10
context.conf.capabilities = [
capabilities.CAP_SYS_ADMIN, capabilities.CAP_NET_ADMIN]
context.conf.logger_name = 'oslo_privsep.daemon'
vars(context).update(context_attrs)
vars(context.conf).update(conf_attrs)
return context
@testctx.context.entrypoint
def logme(level, msg, exc_info=False):
# We want to make sure we log everything from the priv side for
@ -152,12 +166,7 @@ class DaemonTest(base.BaseTestCase):
def test_drop_privs(self, mock_dropcaps, mock_keepcaps,
mock_setgroups, mock_setgid, mock_setuid):
channel = mock.NonCallableMock()
context = mock.NonCallableMock()
context.conf.user = 42
context.conf.group = 84
context.conf.thread_pool_size = 10
context.conf.capabilities = [
capabilities.CAP_SYS_ADMIN, capabilities.CAP_NET_ADMIN]
context = get_fake_context()
d = daemon.Daemon(channel, context)
d._drop_privs()
@ -200,23 +209,51 @@ class ClientChannelTestCase(base.BaseTestCase):
def setUp(self):
super(ClientChannelTestCase, self).setUp()
context = get_fake_context()
with mock.patch.object(comm.ClientChannel, '__init__'), \
mock.patch.object(daemon._ClientChannel, 'exchange_ping'):
self.client_channel = daemon._ClientChannel(mock.ANY)
self.client_channel = daemon._ClientChannel(mock.ANY, context)
def test_out_of_band_log_message(self):
@mock.patch.object(daemon.LOG.logger, 'handle')
def test_out_of_band_log_message(self, handle_mock):
message = [daemon.Message.LOG, self.DICT]
self.assertEqual(self.client_channel.log, daemon.LOG)
with mock.patch.object(pylogging, 'makeLogRecord') as mock_make_log, \
mock.patch.object(daemon.LOG, 'isEnabledFor',
return_value=False):
return_value=True) as mock_enabled:
self.client_channel.out_of_band(message)
mock_make_log.assert_called_once_with(self.EXPECTED)
handle_mock.assert_called_once_with(mock_make_log.return_value)
mock_enabled.assert_called_once_with(
mock_make_log.return_value.levelno)
def test_out_of_band_not_log_message(self):
with mock.patch.object(daemon.LOG, 'warning') as mock_warning:
self.client_channel.out_of_band([daemon.Message.PING])
mock_warning.assert_called_once()
@mock.patch.object(daemon.logging, 'getLogger')
@mock.patch.object(pylogging, 'makeLogRecord')
def test_out_of_band_log_message_context_logger(self, make_log_mock,
get_logger_mock):
logger_name = 'os_brick.privileged'
context = get_fake_context(conf_attrs={'logger_name': logger_name})
with mock.patch.object(comm.ClientChannel, '__init__'), \
mock.patch.object(daemon._ClientChannel, 'exchange_ping'):
channel = daemon._ClientChannel(mock.ANY, context)
get_logger_mock.assert_called_once_with(logger_name)
self.assertEqual(get_logger_mock.return_value, channel.log)
message = [daemon.Message.LOG, self.DICT]
channel.out_of_band(message)
make_log_mock.assert_called_once_with(self.EXPECTED)
channel.log.isEnabledFor.assert_called_once_with(
make_log_mock.return_value.levelno)
channel.log.logger.handle.assert_called_once_with(
make_log_mock.return_value)
class UnMonkeyPatch(base.BaseTestCase):

View File

@ -0,0 +1,15 @@
---
features:
- |
``PrivContext`` accepts a new string parameter called ``logger_name`` to
define the logger we want to use for the daemon logs of this context.
By default all contexts use ``oslo_privsep.daemon``, but in some cases we
may need finer grained log levels, for example nova running in debug mode
could log its own privsep calls on INFO level regardless, but leave all
libraries' privsep calls, such as os-brick's, to be logged in the normal
DEBUG level.
See `bug 1922052`_.
.. _`bug 1922052`: https://bugs.launchpad.net/nova/+bug/1922052