More sophisticated logging on privileged side

Any python logging messages generated on the privileged side (that
exceed the python logging level) are sent to the unprivileged side,
where the actual write to the regular oslo.log logger occurs.

Before, those priv->unpriv logging messages were dumb lines written to
stderr.  This meant the original severity level was lost, and the unpriv
side made the arbitrary/conservative choice to always log them at WARNING.

With this change, those priv->unpriv logging messages are sent down the
regular priv<->unpriv communication channel using a new "out of band"
mechanism.  The messages now include the original severity level, which
the unpriv side now honours.  And there was much rejoicing.

Any lines that *do* end up on stderr (using the exec method) will
continue to be logged at WARNING, since these will most likely be
"privsep-helper command not found" or similarly important.

Change-Id: Ifc63aedbec4ababefd2138cb73b348e2698db4ad
Closes-Bug: #1593743

oslo_privsep/comm.py

@@ -124,6 +124,9 @@ class ClientChannel(object):
         """This thread owns and demuxes the read channel"""
         for msg in reader:
             msgid, data = msg
+            if msgid is None:
+                self.out_of_band(data)
+            else:
                 with self.lock:
                     assert msgid in self.outstanding_msgs
                     self.outstanding_msgs[msgid].set_result(data)
@@ -139,6 +142,10 @@ class ClientChannel(object):
             for mbox in self.outstanding_msgs.values():
                 mbox.set_exception(exc)
 
+    def out_of_band(self, msg):
+        """Received OOB message. Subclasses might want to override this."""
+        pass
+
     def send_recv(self, msg):
         myid = _get_thread_ident()
         future = Future(self.lock)

oslo_privsep/daemon.py

@@ -67,7 +67,7 @@ from oslo_utils import importutils
 
 from oslo_privsep import capabilities
 from oslo_privsep import comm
-from oslo_privsep._i18n import _, _LE, _LI
+from oslo_privsep._i18n import _, _LE, _LI, _LW
 
 
 LOG = logging.getLogger(__name__)
@@ -95,6 +95,7 @@ class Message(enum.IntEnum):
     CALL = 3
     RET = 4
     ERR = 5
+    LOG = 6
 
 
 class FailedToDropPrivileges(Exception):
@@ -140,6 +141,17 @@ def setgid(group_id_or_name):
             raise FailedToDropPrivileges(msg)
 
 
+class PrivsepLogHandler(pylogging.Handler):
+    def __init__(self, channel):
+        super(PrivsepLogHandler, self).__init__()
+        self.channel = channel
+
+    def emit(self, record):
+        self.channel.send((None, (Message.LOG,
+                                  record.levelno,
+                                  record.getMessage())))
+
+
 class _ClientChannel(comm.ClientChannel):
     """Our protocol, layered on the basic primitives in comm.ClientChannel"""
 
@@ -176,6 +188,14 @@ class _ClientChannel(comm.ClientChannel):
         else:
             raise ProtocolError(_('Unexpected response: %r') % result)
 
+    def out_of_band(self, msg):
+        if msg[0] == Message.LOG:
+            # (LOG, level, message)
+            LOG.log(msg[1], msg[2])
+        else:
+            LOG.warn(_LW('Ignoring unexpected OOB message from privileged '
+                         'process: %r'), msg)
+
 
 def fdopen(fd, *args, **kwargs):
     # NOTE(gus): We can't just use os.fdopen() here and allow the
@@ -236,16 +256,16 @@ class ForkingClientChannel(_ClientChannel):
         for f in (sys.stdout, sys.stderr):
             f.flush()
 
-        log_fd = _fd_logger()
-
         if os.fork() == 0:
             # child
 
-            # replace root logger early (to capture any errors below)
-            replace_logging(pylogging.StreamHandler(log_fd))
-
+            channel = comm.ServerChannel(sock_b)
             sock_a.close()
-            Daemon(comm.ServerChannel(sock_b), context=context).run()
+
+            # Replace root logger early (to capture any errors during setup)
+            replace_logging(PrivsepLogHandler(channel))
+
+            Daemon(channel, context=context).run()
             LOG.debug('privsep daemon exiting')
             os._exit(0)
 
@@ -435,12 +455,7 @@ def helper_main():
     logging.register_options(cfg.CONF)
 
     cfg.CONF(args=sys.argv[1:], project='privsep')
-    logging.setup(cfg.CONF, 'privsep')
-
-    # We always log to stderr.  Replace the root logger we just set up.
-    replace_logging(pylogging.StreamHandler(sys.stderr))
-
-    LOG.info(_LI('privsep daemon starting'))
+    logging.setup(cfg.CONF, 'privsep')  # note replace_logging call below
 
     context = importutils.import_class(cfg.CONF.privsep_context)
     from oslo_privsep import priv_context   # Avoid circular import
@@ -464,6 +479,11 @@ def helper_main():
     # regular daemon might, since we _want_ to remain associated with
     # the originating (unprivileged) process.
 
+    # Channel is set up now, so move to in-band logging
+    replace_logging(PrivsepLogHandler(channel))
+
+    LOG.info(_LI('privsep daemon starting'))
+
     try:
         Daemon(channel, context).run()
     except Exception as e:

oslo_privsep/tests/test_daemon.py

@@ -13,11 +13,11 @@
 #    under the License.
 
 import fixtures
-import logging
 import mock
 import platform
 import time
 
+from oslo_log import log as logging
 from oslotest import base
 import testtools
 
@@ -35,7 +35,10 @@ def undecorated():
 
 @testctx.context.entrypoint
 def logme(level, msg):
-    LOG.log(level, '%s', msg)
+    # We want to make sure we log everything from the priv side for
+    # the purposes of this test, so force loglevel.
+    LOG.logger.setLevel(logging.DEBUG)
+    LOG.log(level, msg)
 
 
 @testtools.skipIf(platform.system() != 'Linux',
@@ -47,17 +50,14 @@ class LogTest(testctx.TestContextTestCase):
             name=None, level=logging.INFO))
 
     def test_priv_log(self):
+        # These write to the log on the priv side
         logme(logging.DEBUG, u'test@DEBUG')
         logme(logging.WARN, u'test@WARN')
 
         time.sleep(0.1)  # Hack to give logging thread a chance to run
 
-        # TODO(gus): Currently severity information is lost and
-        # everything is logged as INFO.  Fixing this probably requires
-        # writing structured messages to the logging socket.
-        #
-        # self.assertNotIn('test@DEBUG', self.logger.output)
-
+        # self.logger.output is the resulting log on the unpriv side
+        self.assertNotIn(u'test@DEBUG', self.logger.output)
         self.assertIn(u'test@WARN', self.logger.output)