Merge "Preserve all LogRecord fields from privileged side"

oslo_privsep/daemon.py

@@ -142,14 +142,30 @@ def setgid(group_id_or_name):
 
 
 class PrivsepLogHandler(pylogging.Handler):
-    def __init__(self, channel):
+    def __init__(self, channel, processName=None):
         super(PrivsepLogHandler, self).__init__()
         self.channel = channel
+        self.processName = processName
 
     def emit(self, record):
-        self.channel.send((None, (Message.LOG,
-                                  record.levelno,
-                                  record.getMessage())))
+        # Vaguely based on pylogging.handlers.SocketHandler.makePickle
+
+        if self.processName:
+            record.processName = self.processName
+
+        data = dict(record.__dict__)
+
+        if record.exc_info:
+            if not record.exc_text:
+                fmt = self.formatter or pylogging.Formatter()
+                data['exc_text'] = fmt.formatException(record.exc_info)
+            data['exc_info'] = None  # drop traceback in favor of exc_text
+
+        # serialise msg now so we can drop (potentially unserialisable) args
+        data['msg'] = record.getMessage()
+        data['args'] = None
+
+        self.channel.send((None, (Message.LOG, data)))
 
 
 class _ClientChannel(comm.ClientChannel):
@@ -190,8 +206,10 @@ class _ClientChannel(comm.ClientChannel):
 
     def out_of_band(self, msg):
         if msg[0] == Message.LOG:
-            # (LOG, level, message)
-            LOG.log(msg[1], msg[2])
+            # (LOG, LogRecord __dict__)
+            record = pylogging.makeLogRecord(msg[1])
+            if LOG.isEnabledFor(record.levelno):
+                LOG.logger.handle(record)
         else:
             LOG.warning(_LW('Ignoring unexpected OOB message from privileged '
                             'process: %r'), msg)
@@ -263,7 +281,8 @@ class ForkingClientChannel(_ClientChannel):
             sock_a.close()
 
             # Replace root logger early (to capture any errors during setup)
-            replace_logging(PrivsepLogHandler(channel))
+            replace_logging(PrivsepLogHandler(channel,
+                                              processName=str(context)))
 
             Daemon(channel, context=context).run()
             LOG.debug('privsep daemon exiting')

oslo_privsep/tests/test_daemon.py

@@ -12,7 +12,10 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
+import copy
 import fixtures
+import functools
+import logging as pylogging
 import mock
 import platform
 import time
@@ -33,12 +36,32 @@ def undecorated():
     pass
 
 
+class TestException(Exception):
+    pass
+
+
 @testctx.context.entrypoint
-def logme(level, msg):
+def logme(level, msg, exc_info=False):
     # 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)
+    if exc_info:
+        try:
+            raise TestException('with arg')
+        except TestException:
+            LOG.log(level, msg, exc_info=True)
+    else:
+        LOG.log(level, msg)
+
+
+class LogRecorder(pylogging.Formatter):
+    def __init__(self, logs, *args, **kwargs):
+        super(LogRecorder, self).__init__(*args, **kwargs)
+        self.logs = logs
+
+    def format(self, record):
+        self.logs.append(copy.deepcopy(record))
+        return super(LogRecorder, self).format(record)
 
 
 @testtools.skipIf(platform.system() != 'Linux',
@@ -46,19 +69,46 @@ def logme(level, msg):
 class LogTest(testctx.TestContextTestCase):
     def setUp(self):
         super(LogTest, self).setUp()
-        self.logger = self.useFixture(fixtures.FakeLogger(
-            name=None, level=logging.INFO))
 
-    def test_priv_log(self):
+    def test_priv_loglevel(self):
+        logger = self.useFixture(fixtures.FakeLogger(
+            level=logging.INFO))
+
         # 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
 
-        # 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)
+        # logger.output is the resulting log on the unpriv side.
+        # This should have been filtered based on (unpriv) loglevel.
+        self.assertNotIn(u'test@DEBUG', logger.output)
+        self.assertIn(u'test@WARN', logger.output)
+
+    def test_record_data(self):
+        logs = []
+
+        self.useFixture(fixtures.FakeLogger(
+            level=logging.INFO, format='dummy',
+            # fixtures.FakeLogger accepts only a formatter
+            # class/function, not an instance :(
+            formatter=functools.partial(LogRecorder, logs)))
+
+        logme(logging.WARN, u'test with exc', exc_info=True)
+
+        time.sleep(0.1)  # Hack to give logging thread a chance to run
+
+        self.assertEqual(1, len(logs))
+
+        record = logs[0]
+        self.assertIn(u'test with exc', record.getMessage())
+        self.assertEqual(None, record.exc_info)
+        self.assertIn(u'TestException: with arg', record.exc_text)
+        self.assertEqual('PrivContext(cfg_section=privsep)',
+                         record.processName)
+        self.assertIn(u'test_daemon.py', record.exc_text)
+        self.assertEqual(logging.WARN, record.levelno)
+        self.assertEqual('logme', record.funcName)
 
 
 @testtools.skipIf(platform.system() != 'Linux',