From 1b012d0fc6811f00e032e52ed586fe37e157584d Mon Sep 17 00:00:00 2001 From: Juan Antonio Osorio Robles Date: Mon, 6 Nov 2017 08:59:43 +0000 Subject: [PATCH] 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 | 32 +++++++++++++------ oslo_log/tests/unit/test_log.py | 29 ++++++++++++++--- .../add-context-section-0b2f411ec64f42f6.yaml | 6 ++++ 3 files changed, 53 insertions(+), 14 deletions(-) create mode 100644 releasenotes/notes/add-context-section-0b2f411ec64f42f6.yaml diff --git a/oslo_log/formatters.py b/oslo_log/formatters.py index ae2d04d8..7fd5d429 100644 --- a/oslo_log/formatters.py +++ b/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 - # dictionary because the values are more useful than the + # The context object might have been given from the logging call. if + # 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: - extra.update(_dictify_context(context)) - del extra['context'] + if 'context' in extra and extra['context']: + message['context'] = _dictify_context(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 - # dictionary because the values are more useful than the + # The context object might have been given from the logging call. if + # 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: - extra.update(_dictify_context(context)) - del extra['context'] + if 'context' in extra and extra['context']: + message['context'] = _dictify_context(extra['context']) + elif context: + message['context'] = _dictify_context(context) + else: + message['context'] = {} + extra.pop('context', None) message['extra'] = extra if record.exc_info: diff --git a/oslo_log/tests/unit/test_log.py b/oslo_log/tests/unit/test_log.py index 6d63b2d9..a35cc178 100644 --- a/oslo_log/tests/unit/test_log.py +++ b/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']) diff --git a/releasenotes/notes/add-context-section-0b2f411ec64f42f6.yaml b/releasenotes/notes/add-context-section-0b2f411ec64f42f6.yaml new file mode 100644 index 00000000..200463cf --- /dev/null +++ b/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.