From 71c732c8337309b3dc1b5a1957255da617d8dc3f Mon Sep 17 00:00:00 2001 From: Gorka Eguileor Date: Tue, 30 Mar 2021 18:59:18 +0200 Subject: [PATCH] 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 --- oslo_privsep/daemon.py | 20 ++++--- oslo_privsep/priv_context.py | 8 ++- oslo_privsep/tests/test_daemon.py | 55 ++++++++++++++++--- .../context-logger-06b475357bebadc7.yaml | 15 +++++ 4 files changed, 79 insertions(+), 19 deletions(-) create mode 100644 releasenotes/notes/context-logger-06b475357bebadc7.yaml diff --git a/oslo_privsep/daemon.py b/oslo_privsep/daemon.py index 3297e72..cde8f52 100644 --- a/oslo_privsep/daemon.py +++ b/oslo_privsep/daemon.py @@ -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): diff --git a/oslo_privsep/priv_context.py b/oslo_privsep/priv_context.py index 2b81787..58b4b5e 100644 --- a/oslo_privsep/priv_context.py +++ b/oslo_privsep/priv_context.py @@ -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): diff --git a/oslo_privsep/tests/test_daemon.py b/oslo_privsep/tests/test_daemon.py index 01eb52b..f391e97 100644 --- a/oslo_privsep/tests/test_daemon.py +++ b/oslo_privsep/tests/test_daemon.py @@ -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): diff --git a/releasenotes/notes/context-logger-06b475357bebadc7.yaml b/releasenotes/notes/context-logger-06b475357bebadc7.yaml new file mode 100644 index 0000000..8d4e5ec --- /dev/null +++ b/releasenotes/notes/context-logger-06b475357bebadc7.yaml @@ -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