Add support for using extra={...} on stdlib loggers

Author: sethmlarson

README.md

@@ -42,16 +42,21 @@ handler.setFormatter(ecs_logging.StdlibFormatter())
 logger.addHandler(handler)
 
 # Emit a log!
-logger.debug("Example message!")
+logger.debug("Example message!", extra={"http.request.method": "get"})
 ```
 ```json
 {
     "@timestamp": "2020-03-20T18:11:37.895Z",
     "ecs": {
         "version": "1.5.0"
     },
+    "http": {
+      "request": {
+        "method": "get"
+      }
+    },
     "log": {
-        "level": "DEBUG",
+        "level": "debug",
         "logger": "app",
         "origin": {
             "file": {

ecs_logging/_stdlib.py

@@ -18,6 +18,28 @@ class StdlibFormatter(logging.Formatter):
         "message": "log.original",
         "name": "log.logger",
     }
+    LOGRECORD_DICT = {
+        "name",
+        "msg",
+        "args",
+        "levelname",
+        "levelno",
+        "pathname",
+        "filename",
+        "module",
+        "exc_info",
+        "exc_text",
+        "stack_info",
+        "lineno",
+        "funcName",
+        "created",
+        "msecs",
+        "relativeCreated",
+        "thread",
+        "threadName",
+        "processName",
+        "process",
+    }
     converter = time.gmtime
 
     def __init__(self):
@@ -48,9 +70,15 @@ def format_to_ecs(self, record):
         available["message"] = record.getMessage()
 
         for attribute in set(self.WANTED_ATTRS).intersection(available):
-            merge_dicts(
-                de_dot(self.WANTED_ATTRS[attribute], getattr(record, attribute)), result
-            )
+            ecs_attr = self.WANTED_ATTRS[attribute]
+            value = getattr(record, attribute)
+            if ecs_attr == "log.level" and isinstance(value, str):
+                value = value.lower()
+            merge_dicts(de_dot(ecs_attr, value), result)
+
+        # Merge in any keys that were set within 'extra={...}'
+        for key in set(available.keys()).difference(self.LOGRECORD_DICT):
+            merge_dicts(de_dot(key, available[key]), result)
 
         # The following is mostly for the ecs format. You can't have 2x
         # 'message' keys in WANTED_ATTRS, so we set the value to

ecs_logging/_structlog.py

@@ -13,7 +13,7 @@ class StructlogFormatter:
     def __call__(self, _, name, event_dict):
         # type: (Any, str, Dict[str, Any]) -> str
         event_dict = normalize_dict(event_dict)
-        event_dict.setdefault("log", {}).setdefault("level", name)
+        event_dict.setdefault("log", {}).setdefault("level", name.lower())
         event_dict = self.format_to_ecs(event_dict)
         return json_dumps(event_dict)
 

tests/test_stdlib_formatter.py

@@ -1,4 +1,5 @@
 import logging
+import mock
 import ecs_logging
 from .compat import StringIO
 
@@ -24,7 +25,7 @@ def test_record_formatted():
 
     assert formatter.format(make_record()) == (
         '{"@timestamp":"2020-03-20T14:12:46.123Z","ecs":{"version":"1.5.0"},'
-        '"log":{"level":"DEBUG","logger":"logger-name","origin":{"file":{"line":10,"name":"file.py"},'
+        '"log":{"level":"debug","logger":"logger-name","origin":{"file":{"line":10,"name":"file.py"},'
         '"function":"test_function"},"original":"1: hello"},"message":"1: hello"}'
     )
 
@@ -39,7 +40,7 @@ def format_to_ecs(self, record):
     formatter = CustomFormatter()
     assert formatter.format(make_record()) == (
         '{"@timestamp":"2020-03-20T14:12:46.123Z","custom":"field","ecs":{"version":"1.5.0"},'
-        '"log":{"level":"DEBUG","logger":"logger-name","origin":{"file":{"line":10,"name":"file.py"},'
+        '"log":{"level":"debug","logger":"logger-name","origin":{"file":{"line":10,"name":"file.py"},'
         '"function":"test_function"},"original":"1: hello"},"message":"1: hello"}'
     )
 
@@ -53,6 +54,27 @@ def test_can_be_set_on_handler():
 
     assert stream.getvalue() == (
         '{"@timestamp":"2020-03-20T14:12:46.123Z","ecs":{"version":"1.5.0"},'
-        '"log":{"level":"DEBUG","logger":"logger-name","origin":{"file":{"line":10,"name":"file.py"},'
+        '"log":{"level":"debug","logger":"logger-name","origin":{"file":{"line":10,"name":"file.py"},'
         '"function":"test_function"},"original":"1: hello"},"message":"1: hello"}\n'
     )
+
+
+@mock.patch("time.time")
+def test_extra_is_merged(time):
+    time.return_value = 1584720997.187709
+
+    stream = StringIO()
+    handler = logging.StreamHandler(stream)
+    handler.setFormatter(ecs_logging.StdlibFormatter())
+    logger = logging.getLogger("test-logger")
+    logger.addHandler(handler)
+    logger.setLevel(logging.INFO)
+
+    logger.info("hey world", extra={"tls": {"cipher": "AES"}, "tls.established": True})
+
+    assert stream.getvalue() == (
+        '{"@timestamp":"2020-03-20T16:16:37.187Z","ecs":{"version":"1.5.0"},"log":'
+        '{"level":"info","logger":"test-logger","origin":{"file":{"line":73,"name":'
+        '"test_stdlib_formatter.py"},"function":"test_extra_is_merged"},"original":"hey '
+        'world"},"message":"hey world","tls":{"cipher":"AES","established":true}}\n'
+    )