Capture context in its own key for JSON-based formatters

The JSON formatter used to rely on services making their logging calls
and passing the context there. A call it expted would be

    LOG.debug("Some message", context=context)

This would end up in the "extra" section of the logging record. This is
not usually the case, as projects don't always pass the context on that
call. This also applies to the Fluent formatter which is based on the
JSON one.

For the JSON formatter, we already are getting the context from the
record. So lets use that if no context was provided in the record's
'extra' section. Finally, this places the context in its own section,
which is named 'context'.

Closes-Bug: #1730329
Depends-On: I2b245c1665c3587be3c476b803122788d186e5d5
Change-Id: I765dae17d2ecadce1672f16e432e748d5233acf8

oslo_log/formatters.py

@@ -221,12 +221,18 @@ class JSONFormatter(logging.Formatter):
         for key in getattr(record, 'extra_keys', []):
             if key not in extra:
                 extra[key] = getattr(record, key)
-        # If we saved a context object, explode it into the extra
+        # The context object might have been given from the logging call. if
-        # dictionary because the values are more useful than the
+        # that was the case, it'll come in the 'extra' entry already. If not,
+        # lets use the context we fetched above. In either case, we explode it
+        # into the 'context' entry because the values are more useful than the
         # object reference.
-        if 'context' in extra:
+        if 'context' in extra and extra['context']:
-            extra.update(_dictify_context(context))
+            message['context'] = _dictify_context(extra['context'])
-            del extra['context']
+        elif context:
+            message['context'] = _dictify_context(context)
+        else:
+            message['context'] = {}
+        extra.pop('context', None)
         message['extra'] = extra
 
         if record.exc_info:
@@ -290,12 +296,18 @@ class FluentFormatter(logging.Formatter):
         for key in getattr(record, 'extra_keys', []):
             if key not in extra:
                 extra[key] = getattr(record, key)
-        # If we saved a context object, explode it into the extra
+        # The context object might have been given from the logging call. if
-        # dictionary because the values are more useful than the
+        # that was the case, it'll come in the 'extra' entry already. If not,
+        # lets use the context we fetched above. In either case, we explode it
+        # into the extra dictionary because the values are more useful than the
         # object reference.
-        if 'context' in extra:
+        if 'context' in extra and extra['context']:
-            extra.update(_dictify_context(context))
+            message['context'] = _dictify_context(extra['context'])
-            del extra['context']
+        elif context:
+            message['context'] = _dictify_context(context)
+        else:
+            message['context'] = {}
+        extra.pop('context', None)
         message['extra'] = extra
 
         if record.exc_info:

oslo_log/tests/unit/test_log.py

@@ -415,18 +415,38 @@ class JSONFormatterTestCase(LogTestBase):
                                        formatter=formatters.JSONFormatter)
         self._set_log_level_with_cleanup(self.log, logging.DEBUG)
 
-    def test_json(self):
+    def test_json_w_context_in_extras(self):
         test_msg = 'This is a %(test)s line'
         test_data = {'test': 'log'}
         local_context = _fake_context()
         self.log.debug(test_msg, test_data, key='value', context=local_context)
+        self._validate_json_data('test_json_w_context_in_extras', test_msg,
+                                 test_data, local_context)
 
+    def test_json_w_fetched_global_context(self):
+        test_msg = 'This is a %(test)s line'
+        test_data = {'test': 'log'}
+        local_context = _fake_context()
+        # NOTE we're not passing the context explicitly here. But it'll add the
+        # context to the extras anyway since the call to fake_context adds the
+        # context to the thread. The context will be fetched with the
+        # _update_record_with_context call that's done in the formatter.
+        self.log.debug(test_msg, test_data, key='value')
+        self._validate_json_data('test_json_w_fetched_global_context',
+                                 test_msg, test_data, local_context)
+
+    def _validate_json_data(self, testname, test_msg, test_data, ctx):
         data = jsonutils.loads(self.stream.getvalue())
         self.assertTrue(data)
         self.assertIn('extra', data)
+        self.assertIn('context', data)
         extra = data['extra']
+        context = data['context']
+        self.assertNotIn('context', extra)
         self.assertEqual('value', extra['key'])
-        self.assertEqual(local_context.user, extra['user'])
+        self.assertEqual(ctx.user, context['user'])
+        self.assertEqual(ctx.user_name, context['user_name'])
+        self.assertEqual(ctx.project_name, context['project_name'])
         self.assertEqual('test-json', data['name'])
 
         self.assertEqual(test_msg % test_data, data['message'])
@@ -434,7 +454,7 @@ class JSONFormatterTestCase(LogTestBase):
         self.assertEqual(test_data, data['args'])
 
         self.assertEqual('test_log.py', data['filename'])
-        self.assertEqual('test_json', data['funcname'])
+        self.assertEqual(testname, data['funcname'])
 
         self.assertEqual('DEBUG', data['levelname'])
         self.assertEqual(logging.DEBUG, data['levelno'])
@@ -563,8 +583,9 @@ class FluentFormatterTestCase(LogTestBase):
         self.assertIn('lineno', data)
         self.assertIn('extra', data)
         extra = data['extra']
+        context = data['context']
         self.assertEqual('value', extra['key'])
-        self.assertEqual(local_context.user, extra['user'])
+        self.assertEqual(local_context.user, context['user'])
         self.assertEqual('test-fluent', data['name'])
 
         self.assertEqual(test_msg % test_data, data['message'])

releasenotes/notes/add-context-section-0b2f411ec64f42f6.yaml

@@ -0,0 +1,6 @@
+---
+features:
+  - |
+    The JSON based formatters (namely JSONFormatter and FluentFormatter) now
+    output an extra section called 'context' that contains the context-related
+    keys and values, e.g. user, project and domain.