Merge "Improve olso.log test coverage for edge cases"

1 files changed, 92 insertions, 21 deletions

diff --git a/oslo_log/tests/unit/test_log.py b/oslo_log/tests/unit/test_log.py
index 1923394..0e1adb3 100644
--- a/oslo_log/tests/unit/test_log.py
+++ b/oslo_log/tests/unit/test_log.py
@@ -370,6 +370,38 @@ class JSONFormatterTestCase(LogTestBase):
         self.assertEqual(logging.ERROR, data['levelno'])
         self.assertTrue(data['traceback'])
 
+    def test_json_with_extra(self):
+        test_msg = 'This is a %(test)s line'
+        test_data = {'test': 'log'}
+        extra_data = {'special_user': 'user1',
+                      'special_tenant': 'unicorns'}
+        self.log.debug(test_msg, test_data, key='value', extra=extra_data)
+
+        data = jsonutils.loads(self.stream.getvalue())
+        self.assertTrue(data)
+        self.assertTrue('extra' in data)
+        for k, v in extra_data.items():
+            self.assertIn(k, data['extra'])
+            self.assertEqual(v, data['extra'][k])
+
+    def test_json_with_extra_keys(self):
+        test_msg = 'This is a %(test)s line'
+        test_data = {'test': 'log'}
+        extra_keys = ['special_tenant', 'special_user']
+        special_tenant = 'unicorns'
+        special_user = 'user2'
+        self.log.debug(test_msg, test_data, key='value',
+                       extra_keys=extra_keys, special_tenant=special_tenant,
+                       special_user=special_user)
+
+        data = jsonutils.loads(self.stream.getvalue())
+        self.assertTrue(data)
+        self.assertTrue('extra' in data)
+        self.assertTrue(extra_keys[0] in data['extra'])
+        self.assertEqual(special_tenant, data['extra'][extra_keys[0]])
+        self.assertTrue(extra_keys[1] in data['extra'])
+        self.assertEqual(special_user, data['extra'][extra_keys[1]])
+
 
 def get_fake_datetime(retval):
     class FakeDateTime(datetime.datetime):
@@ -650,33 +682,28 @@ class FancyRecordTestCase(LogTestBase):
                                    (ctxt.request_id, ctxt.resource_uuid)))
 
     def test_resource_key_in_log_msg(self):
-        infocolor = handlers.ColorHandler.LEVEL_COLORS[logging.INFO]
+        color = handlers.ColorHandler.LEVEL_COLORS[logging.INFO]
         ctxt = _fake_context()
         resource = 'resource-202260f9-1224-490d-afaf-6a744c13141f'
         fake_resource = {'name': resource}
         message = 'info'
         self.colorlog.info(message, context=ctxt, resource=fake_resource)
-        infoexpected = '%s [%s]: [%s] %s\n' % (infocolor,
-                                               ctxt.request_id,
-                                               resource,
-                                               message)
-        self.assertEqual(infoexpected, self.stream.getvalue())
+        expected = ('%s [%s]: [%s] %s\n' %
+                    (color, ctxt.request_id, resource, message))
+        self.assertEqual(expected, self.stream.getvalue())
 
     def test_resource_key_dict_in_log_msg(self):
-        infocolor = handlers.ColorHandler.LEVEL_COLORS[logging.INFO]
+        color = handlers.ColorHandler.LEVEL_COLORS[logging.INFO]
         ctxt = _fake_context()
-        resource_type = 'fake_resource'
+        type = 'fake_resource'
         resource_id = '202260f9-1224-490d-afaf-6a744c13141f'
-        fake_resource = {'type': 'fake_resource',
+        fake_resource = {'type': type,
                          'id': resource_id}
         message = 'info'
         self.colorlog.info(message, context=ctxt, resource=fake_resource)
-        infoexpected = '%s [%s]: [%s-%s] %s\n' % (infocolor,
-                                                  ctxt.request_id,
-                                                  resource_type,
-                                                  resource_id,
-                                                  message)
-        self.assertEqual(infoexpected, self.stream.getvalue())
+        expected = ('%s [%s]: [%s-%s] %s\n' %
+                    (color, ctxt.request_id, type, resource_id, message))
+        self.assertEqual(expected, self.stream.getvalue())
 
 
 class InstanceRecordTestCase(LogTestBase):
@@ -699,18 +726,62 @@ class InstanceRecordTestCase(LogTestBase):
         fake_resource = {'uuid': uuid}
         message = 'info'
         self.log.info(message, context=ctxt, instance=fake_resource)
-        infoexpected = '[%s]: [instance: %s] %s\n' % (ctxt.request_id,
-                                                      uuid,
-                                                      message)
-        self.assertEqual(infoexpected, self.stream.getvalue())
+        expected = ('[%s]: [instance: %s] %s\n' %
+                    (ctxt.request_id, uuid, message))
+        self.assertEqual(expected, self.stream.getvalue())
 
     def test_instance_dict_in_default_log_msg(self):
         uuid = 'C9B7CCC6-8A12-4C53-A736-D7A1C36A62F3'
         fake_resource = {'uuid': uuid}
         message = 'info'
         self.log.info(message, instance=fake_resource)
-        infoexpected = '[instance: %s] %s\n' % (uuid, message)
-        self.assertEqual(infoexpected, self.stream.getvalue())
+        expected = '[instance: %s] %s\n' % (uuid, message)
+        self.assertEqual(expected, self.stream.getvalue())
+
+    def test_instance_uuid_as_arg_in_context_log_msg(self):
+        ctxt = _fake_context()
+        uuid = 'C9B7CCC6-8A12-4C53-A736-D7A1C36A62F3'
+        message = 'info'
+        self.log.info(message, context=ctxt, instance_uuid=uuid)
+        expected = ('[%s]: [instance: %s] %s\n' %
+                    (ctxt.request_id, uuid, message))
+        self.assertEqual(expected, self.stream.getvalue())
+
+    def test_instance_uuid_as_arg_in_default_log_msg(self):
+        uuid = 'C9B7CCC6-8A12-4C53-A736-D7A1C36A62F3'
+        message = 'info'
+        self.log.info(message, instance_uuid=uuid)
+        expected = '[instance: %s] %s\n' % (uuid, message)
+        self.assertEqual(expected, self.stream.getvalue())
+
+    def test_instance_uuid_from_context_in_context_log_msg(self):
+        ctxt = _fake_context()
+        ctxt.instance_uuid = 'CCCCCCCC-8A12-4C53-A736-D7A1C36A62F3'
+        message = 'info'
+        self.log.info(message, context=ctxt)
+        expected = ('[%s]: [instance: %s] %s\n' %
+                    (ctxt.request_id, ctxt.instance_uuid, message))
+        self.assertEqual(expected, self.stream.getvalue())
+
+    def test_resource_uuid_from_context_in_context_log_msg(self):
+        ctxt = _fake_context()
+        ctxt.resource_uuid = 'RRRRRRRR-8A12-4C53-A736-D7A1C36A62F3'
+        message = 'info'
+        self.log.info(message, context=ctxt)
+        expected = ('[%s]: [instance: %s] %s\n' %
+                    (ctxt.request_id, ctxt.resource_uuid, message))
+        self.assertEqual(expected, self.stream.getvalue())
+
+    def test_instance_from_context_in_context_log_msg(self):
+        # NOTE: instance when passed in a context object is just a uuid.
+        # When passed to the log record, it is a dict.
+        ctxt = _fake_context()
+        ctxt.instance = 'IIIIIIII-8A12-4C53-A736-D7A1C36A62F3'
+        message = 'info'
+        self.log.info(message, context=ctxt)
+        values = (ctxt.request_id, ctxt.instance, message)
+        expected = '[%s]: [instance: %s] %s\n' % values
+        self.assertEqual(expected, self.stream.getvalue())
 
 
 class TraceLevelTestCase(LogTestBase):