Merge pull request #78 from zencity/FEATURE/77/handle-extra-properties

Implement extra properties from json-logging-py

Author: bobbui

README.md

@@ -245,12 +245,14 @@ correlation_id_without_request_obj = json_logging.get_correlation_id()
 
 ## 2.4 Log extra properties
 
-Extra property can be added to logging statement as follow:
+Extra property can be added to logging statement as follows:
 
 ```python
-logger.info("test log statement", extra={'props': {'extra_property': 'extra_value'}})
+logger.info("test log statement", extra={'props': {'extra_property': 'extra_value'}, 'tags': ['app:name']})
 ```
 
+_For backwards compatibility, properties added in `props` are extracted to the root and take precedence over those set directly in the root of `extra`. This is relevant only for logs formatted by `JSONLogFormatter`, other formatters never printed the `props` details._
+
 ### Forced overriding correlation-id
 A custom correlation id can be passed to logging statement as follow:
 ```

json_logging/__init__.py

@@ -25,6 +25,28 @@
 COMPONENT_NAME = EMPTY_VALUE
 COMPONENT_INSTANCE_INDEX = 0
 
+# The list contains all the attributes listed in
+# http://docs.python.org/library/logging.html#logrecord-attributes
+RECORD_ATTR_SKIP_LIST = [
+    'asctime', 'created', 'exc_info', 'exc_text', 'filename', 'args',
+    'funcName', 'id', 'levelname', 'levelno', 'lineno', 'module', 'msg',
+    'msecs', 'msecs', 'message', 'name', 'pathname', 'process',
+    'processName', 'relativeCreated', 'thread', 'threadName', 'extra',
+    # Also exclude legacy 'props'
+    'props',
+]
+
+try:
+    basestring
+except NameError:
+    basestring = str
+
+if sys.version_info < (3, 0):
+    EASY_TYPES = (basestring, bool, dict, float, int, list, type(None))
+else:
+    RECORD_ATTR_SKIP_LIST.append('stack_info')
+    EASY_TYPES = (str, bool, dict, float, int, list, type(None))
+
 _framework_support_map = {}
 _current_framework = None
 _logger = get_library_logger(__name__)
@@ -268,8 +290,29 @@ def _format_log_object(self, record, request_util):
             "written_ts": util.epoch_nano_second(utcnow),
         }
         base_obj.update(self.base_object_common)
+        # Add extra fields
+        base_obj.update(self._get_extra_fields(record))
         return base_obj
 
+    def _get_extra_fields(self, record):
+        fields = {}
+
+        if record.args:
+            fields['msg'] = record.msg
+
+        for key, value in record.__dict__.items():
+            if key not in RECORD_ATTR_SKIP_LIST:
+                if isinstance(value, EASY_TYPES):
+                    fields[key] = value
+                else:
+                    fields[key] = repr(value)
+
+        # Always add 'props' to the root of the log, assumes props is a dict
+        if hasattr(record, 'props') and isinstance(record.props, dict):
+            fields.update(record.props)
+
+        return fields
+
 
 class JSONRequestLogFormatter(BaseJSONFormatter):
     """
@@ -342,8 +385,6 @@ def _format_log_object(self, record, request_util):
             "module": record.module,
             "line_no": record.lineno,
         })
-        if hasattr(record, 'props'):
-            json_log_object.update(record.props)
 
         if record.exc_info or record.exc_text:
             json_log_object.update(self.get_exc_fields(record))

tests/test_fastapi.py

@@ -51,7 +51,15 @@ async def log_error():
     async def extra_property():
         logger.info(
             "test log statement with extra props",
-            extra={"props": {"extra_property": "extra_value"}},
+            extra={"props": {"extra_property": "extra_value"}, "tags": ["app:name"], "extra_property": "extra_value2"},
+        )
+        return {}
+
+    @app.get("/log/extra_property_no_props")
+    async def extra_property_no_props():
+        logger.info(
+            "test log statement with extra and no 'props' property",
+            extra={"tags": ["app:name"], "extra_property": "extra_value2"},
         )
         return {}
 
@@ -148,8 +156,23 @@ def test_extra_property(client_and_log_handler):
     assert response.status_code == 200
     assert len(handler.messages) == 1
     msg = json.loads(handler.messages[0])
-    assert set(msg.keys()) == constants.STANDARD_MSG_ATTRIBUTES.union({"extra_property"})
+    assert set(msg.keys()) == constants.STANDARD_MSG_ATTRIBUTES.union({"extra_property", "tags"})
     assert msg["extra_property"] == "extra_value"
+    assert msg["tags"] == ["app:name"]
+
+
+def test_extra_property_no_props(client_and_log_handler):
+    """Test adding an extra property to a log message"""
+    api_client, handler = client_and_log_handler
+
+    response = api_client.get("/log/extra_property_no_props")
+
+    assert response.status_code == 200
+    assert len(handler.messages) == 1
+    msg = json.loads(handler.messages[0])
+    assert set(msg.keys()) == constants.STANDARD_MSG_ATTRIBUTES.union({"extra_property", "tags"})
+    assert msg["extra_property"] == "extra_value2"
+    assert msg["tags"] == ["app:name"]
 
 
 def test_exception_logged_with_stack_trace(client_and_log_handler):

tests/test_flask.py

@@ -51,7 +51,15 @@ def log_error():
     def extra_property():
         logger.info(
             "test log statement with extra props",
-            extra={"props": {"extra_property": "extra_value"}},
+            extra={"props": {"extra_property": "extra_value"}, "tags": ["app:name"], "extra_property": "extra_value2"},
+        )
+        return {}
+
+    @app.route("/log/extra_property_no_props")
+    def extra_property_no_props():
+        logger.info(
+            "test log statement with extra and no 'props' property",
+            extra={"tags": ["app:name"], "extra_property": "extra_value2"},
         )
         return {}
 
@@ -148,8 +156,23 @@ def test_extra_property(client_and_log_handler):
     assert response.status_code == 200
     assert len(handler.messages) == 1
     msg = json.loads(handler.messages[0])
-    assert set(msg.keys()) == constants.STANDARD_MSG_ATTRIBUTES.union({"extra_property"})
+    assert set(msg.keys()) == constants.STANDARD_MSG_ATTRIBUTES.union({"extra_property", "tags"})
     assert msg["extra_property"] == "extra_value"
+    assert msg["tags"] == ["app:name"]
+
+
+def test_extra_property_no_props(client_and_log_handler):
+    """Test adding an extra property to a log message"""
+    api_client, handler = client_and_log_handler
+
+    response = api_client.get("/log/extra_property_no_props")
+
+    assert response.status_code == 200
+    assert len(handler.messages) == 1
+    msg = json.loads(handler.messages[0])
+    assert set(msg.keys()) == constants.STANDARD_MSG_ATTRIBUTES.union({"extra_property", "tags"})
+    assert msg["extra_property"] == "extra_value2"
+    assert msg["tags"] == ["app:name"]
 
 
 def test_exception_logged_with_stack_trace(client_and_log_handler):