diff --git a/README.md b/README.md index 170f6f2..2388d46 100644 --- a/README.md +++ b/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: ``` diff --git a/json_logging/__init__.py b/json_logging/__init__.py index 36cf842..f3deece 100644 --- a/json_logging/__init__.py +++ b/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)) diff --git a/tests/test_fastapi.py b/tests/test_fastapi.py index a9431a3..73b5750 100644 --- a/tests/test_fastapi.py +++ b/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): diff --git a/tests/test_flask.py b/tests/test_flask.py index 72b39ef..ecf0186 100644 --- a/tests/test_flask.py +++ b/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):