diff --git a/README.md b/README.md index cb81104..c5e2631 100644 --- a/README.md +++ b/README.md @@ -42,7 +42,7 @@ 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 { @@ -50,8 +50,13 @@ logger.debug("Example message!") "ecs": { "version": "1.5.0" }, + "http": { + "request": { + "method": "get" + } + }, "log": { - "level": "DEBUG", + "level": "debug", "logger": "app", "origin": { "file": { diff --git a/ecs_logging/_stdlib.py b/ecs_logging/_stdlib.py index 0356573..8cdaf14 100644 --- a/ecs_logging/_stdlib.py +++ b/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 diff --git a/ecs_logging/_structlog.py b/ecs_logging/_structlog.py index feb11cf..dda4dec 100644 --- a/ecs_logging/_structlog.py +++ b/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) diff --git a/tests/test_stdlib_formatter.py b/tests/test_stdlib_formatter.py index e992584..636ac27 100644 --- a/tests/test_stdlib_formatter.py +++ b/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' + )