Change the default logger behavior to adjust to the majority of APMs

chocs_middleware/trace/logger.py

@@ -71,10 +71,14 @@ class JsonFormatter(logging.Formatter):
     ROOT_TAGS = ["x-request-id", "x-correlation-id", "x-causation-id"]
 
     def __init__(
-        self, json_encoder: json.JSONEncoder = JsonEncoder(), message_format: str = "[{level}] {timestamp} {msg}"
+        self,
+        json_encoder: json.JSONEncoder = JsonEncoder(),
+        message_format: str = "[{level}] {timestamp} {msg}",
+        use_prefix: bool = False
     ):
         self.json_encoder = json_encoder
         self.message_format = message_format
+        self.use_prefix = use_prefix
         super(JsonFormatter, self).__init__()
 
     @staticmethod
@@ -106,7 +110,7 @@ def format(self, record: logging.LogRecord) -> str:
             msg = message
 
         payload = {
-            "log_message": message,
+            "message": message,
             "args": getattr(record, "_message_kwargs", {}),
             "level": record.levelname,
             "timestamp": datetime.utcfromtimestamp(record.created).isoformat(),
@@ -127,7 +131,10 @@ def format(self, record: logging.LogRecord) -> str:
 
         log = {**log, **payload, **{"msg": msg}}
 
-        return self.format_message(log) + "\t" + json.dumps(payload, cls=JsonEncoder, ensure_ascii=True)
+        if self.use_prefix:
+            return self.format_message(log) + "\t" + json.dumps(payload, cls=JsonEncoder, ensure_ascii=True)
+
+        return json.dumps(payload, cls=JsonEncoder, ensure_ascii=True)
 
 
 class Logger(logging.Logger):
@@ -162,6 +169,7 @@ def get(
         log_stream: Optional[IO[str]] = None,
         message_format: str = "[{level}] {timestamp} {msg}",
         propagate: bool = False,
+        use_prefix: bool = False
     ) -> "Logger":
         if name in cls._cache:
             return cls._cache[name]
@@ -173,7 +181,7 @@ def get(
             logger.handlers.clear()
 
         json_handler = logging.StreamHandler(log_stream)
-        json_handler.setFormatter(JsonFormatter(message_format=message_format))
+        json_handler.setFormatter(JsonFormatter(message_format=message_format, use_prefix=use_prefix))
         logger.addHandler(json_handler)
 
         logger.setLevel(level or logging.DEBUG)

pyproject.toml

@@ -1,6 +1,6 @@
 [tool.poetry]
 name = "chocs_middleware.trace"
-version = "0.4.2"
+version = "0.4.3"
 description = "Http tracing middleware for chocs library."
 authors = ["Dawid Kraczkowski <dawid.kraczkowski@gmail.com>"]
 license = "MIT"

tests/trace/test_logger.py

@@ -48,10 +48,9 @@ def test_can_log_message() -> None:
     raw_logs = logger_stream.getvalue().split("\n")[:-1]
 
     for record in raw_logs:
-        json_payload = record[record.find('\t'):]
-        log = json.loads(json_payload)
+        log = json.loads(record)
 
-        assert "log_message" in log
+        assert "message" in log
         assert "args" in log
         assert "level" in log
         assert "timestamp" in log
@@ -71,10 +70,9 @@ def test_can_interpolate_message() -> None:
     # then
     raw_logs = logger_stream.getvalue().split("\n")[:-1]
     record = raw_logs[0]
-    json_payload = record[record.find('\t'):]
-    log = json.loads(json_payload)
+    log = json.loads(record)
 
-    assert log["log_message"] == "hello {name}"
+    assert log["message"] == "hello {name}"
     assert log["args"] == {"name": "test"}
     assert log["level"] == "INFO"
     assert "timestamp" in log
@@ -103,8 +101,7 @@ def test_can_attach_tags() -> None:
     raw_logs = logger_stream.getvalue().split("\n")[:-1]
 
     for record in raw_logs:
-        json_payload = record[record.find('\t'):]
-        log = json.loads(json_payload)
+        log = json.loads(record)
 
         assert "tags" in log
         assert "x-request-id" in log
@@ -127,11 +124,27 @@ def test_can_log_a_dict() -> None:
     # then
     raw_logs = logger_stream.getvalue().split("\n")[:-1]
     record = raw_logs[0]
-    json_payload = record[record.find('\t'):]
-    log = json.loads(json_payload)
+    log = json.loads(record)
 
-    assert log["log_message"] == {"test": "ok"}
+    assert log["message"] == {"test": "ok"}
 
+def test_can_log_with_a_prefix() -> None:
+    # given
+    logger_stream = StringIO()
+    logger = Logger.get("test_can_log_with_a_prefix", log_stream=logger_stream, use_prefix=True)
+
+    # when
+    item = {"test": "ok"}
+    logger.debug("Test log {item}", item=item)
+
+    # then
+    raw_logs = logger_stream.getvalue().split("\n")[:-1]
+    record = raw_logs[0]
+    string_prefix = record[:record.find('\t')]
+    json_payload = json.loads(record[record.find('\t'):])
+
+    assert "Test log {'test': 'ok'}" in string_prefix
+    assert json_payload["message"] == 'Test log {item}'
 
 def test_log_a_dict_in_non_debug_level_as_string() -> None:
     # given
@@ -144,11 +157,10 @@ def test_log_a_dict_in_non_debug_level_as_string() -> None:
     # then
     raw_logs = logger_stream.getvalue().split("\n")[:-1]
     record = raw_logs[0]
-    json_payload = record[record.find('\t'):]
-    log = json.loads(json_payload)
+    log = json.loads(record)
 
     assert log["level"] == "INFO"
-    assert log["log_message"] == str({"test": "ok"})
+    assert log["message"] == str({"test": "ok"})
 
 
 def test_can_retrieve_same_logger_multiple_times() -> None: