From 5d98d4fdec34cf2b98c8f91bdad93cdb6d1c28ca Mon Sep 17 00:00:00 2001 From: Stefan Tjarks <66305+stj@users.noreply.github.com> Date: Wed, 17 Mar 2021 21:43:49 -0700 Subject: [PATCH 1/6] Fix TypeError when exc_info=False Formatting of a message fails in the `StdlibFormatter` when the `exc_info` parameter is `False`. The traceback shows that handling of the boolean is not done correct in the formatting for error type and message. ```python Traceback (most recent call last): File "lib/python3.8/logging/__init__.py", line 1081, in emit msg = self.format(record) File "lib/python3.8/logging/__init__.py", line 925, in format return fmt.format(record) File "ecs_logging/_stdlib.py", line 117, in format result = self.format_to_ecs(record) File "ecs_logging/_stdlib.py", line 163, in format_to_ecs value = extractors[field](record) File "ecs_logging/_stdlib.py", line 150, in if (r.exc_info is not None and r.exc_info[0] is not None) TypeError: 'bool' object is not subscriptable ``` This replaces the lambda with methods handling `exc_info` being an boolean or iterable. --- ecs_logging/_stdlib.py | 28 ++++++++++++++++++++-------- tests/test_stdlib_formatter.py | 16 ++++++++++++++++ 2 files changed, 36 insertions(+), 8 deletions(-) diff --git a/ecs_logging/_stdlib.py b/ecs_logging/_stdlib.py index 2de6e6d..e468fd8 100644 --- a/ecs_logging/_stdlib.py +++ b/ecs_logging/_stdlib.py @@ -112,6 +112,24 @@ def __init__(self, stack_trace_limit=None, exclude_fields=()): self._exclude_fields = frozenset(exclude_fields) self._stack_trace_limit = stack_trace_limit + def _record_error_type(self, record): + # upstream doesn't handle booleans for `exc_info` + if not record.exc_info: + return None + if isinstance(record.exc_info, bool): + return sys.exc_info()[0].__name__ + if isinstance(record.exc_info, (list, tuple)) and record.exc_info[0] is not None: + return record.exc_info[0].__name__ + + def _record_error_message(self, record): + # upstream doesn't handle booleans for `exc_info` + if not record.exc_info: + return None + if isinstance(record.exc_info, bool): + return sys.exc_info()[1].__name__ + elif isinstance(record.exc_info, (list, tuple)) and record.exc_info[1]: + return str(record.exc_info[1]) + def format(self, record): # type: (logging.LogRecord) -> str result = self.format_to_ecs(record) @@ -145,14 +163,8 @@ def format_to_ecs(self, record): "process.name": self._record_attribute("processName"), "process.thread.id": self._record_attribute("thread"), "process.thread.name": self._record_attribute("threadName"), - "error.type": lambda r: ( - r.exc_info[0].__name__ - if (r.exc_info is not None and r.exc_info[0] is not None) - else None - ), - "error.message": lambda r: ( - str(r.exc_info[1]) if r.exc_info and r.exc_info[1] else None - ), + "error.type": self._record_error_type, + "error.message": self._record_error_message, "error.stack_trace": self._record_error_stack_trace, } # type: Dict[str, Callable[[logging.LogRecord],Any]] diff --git a/tests/test_stdlib_formatter.py b/tests/test_stdlib_formatter.py index a6758af..75e791a 100644 --- a/tests/test_stdlib_formatter.py +++ b/tests/test_stdlib_formatter.py @@ -183,6 +183,22 @@ def test_stack_trace_limit_disabled(stack_trace_limit, logger): assert ecs["log"]["original"] == "there was an error" +def test_exc_info_false_does_not_raise(logger): + stream = StringIO() + handler = logging.StreamHandler(stream) + handler.setFormatter( + ecs_logging.StdlibFormatter() + ) + logger.addHandler(handler) + logger.setLevel(logging.DEBUG) + + logger.info("there was %serror", "no ", exc_info=False) + + ecs = json.loads(stream.getvalue().rstrip()) + assert ecs["log.level"] == "info" + assert ecs["message"] == "there was no error" + + def test_stack_trace_limit_traceback(logger): def f(): g() From ea366500d8584e6aad5b0dd8dddfb5123dc2292b Mon Sep 17 00:00:00 2001 From: Stefan Tjarks <66305+stj@users.noreply.github.com> Date: Thu, 18 Mar 2021 08:48:08 -0700 Subject: [PATCH 2/6] PR review comments --- ecs_logging/_stdlib.py | 34 ++++++++++++++++++++++------------ tests/test_stdlib_formatter.py | 4 +--- 2 files changed, 23 insertions(+), 15 deletions(-) diff --git a/ecs_logging/_stdlib.py b/ecs_logging/_stdlib.py index e468fd8..28413dc 100644 --- a/ecs_logging/_stdlib.py +++ b/ecs_logging/_stdlib.py @@ -113,22 +113,32 @@ def __init__(self, stack_trace_limit=None, exclude_fields=()): self._stack_trace_limit = stack_trace_limit def _record_error_type(self, record): - # upstream doesn't handle booleans for `exc_info` - if not record.exc_info: + # type: (logging.LogRecord) -> Optional[str] + exc_info = record.exc_info + if not exc_info: + # exc_info is either an iterable or bool. If it doesn't + # evaluate to True, then no error type used. return None - if isinstance(record.exc_info, bool): - return sys.exc_info()[0].__name__ - if isinstance(record.exc_info, (list, tuple)) and record.exc_info[0] is not None: - return record.exc_info[0].__name__ + if isinstance(exc_info, bool): + # if it is a bool, then look at sys.exc_info + exc_info = sys.exc_info() + if isinstance(exc_info, (list, tuple)) and exc_info[0] is not None: + return exc_info[0].__name__ + return None def _record_error_message(self, record): - # upstream doesn't handle booleans for `exc_info` - if not record.exc_info: + # type: (logging.LogRecord) -> Optional[str] + exc_info = record.exc_info + if not exc_info: + # exc_info is either an iterable or bool. If it doesn't + # evaluate to True, then no error message is used. return None - if isinstance(record.exc_info, bool): - return sys.exc_info()[1].__name__ - elif isinstance(record.exc_info, (list, tuple)) and record.exc_info[1]: - return str(record.exc_info[1]) + if isinstance(exc_info, bool): + # if it is a bool, then look at sys.exc_info + exc_info = sys.exc_info() + if isinstance(exc_info, (list, tuple)) and exc_info[1]: + return str(exc_info[1]) + return None def format(self, record): # type: (logging.LogRecord) -> str diff --git a/tests/test_stdlib_formatter.py b/tests/test_stdlib_formatter.py index 75e791a..e7f7f49 100644 --- a/tests/test_stdlib_formatter.py +++ b/tests/test_stdlib_formatter.py @@ -186,9 +186,7 @@ def test_stack_trace_limit_disabled(stack_trace_limit, logger): def test_exc_info_false_does_not_raise(logger): stream = StringIO() handler = logging.StreamHandler(stream) - handler.setFormatter( - ecs_logging.StdlibFormatter() - ) + handler.setFormatter(ecs_logging.StdlibFormatter()) logger.addHandler(handler) logger.setLevel(logging.DEBUG) From 3236c9e033a96469e5fbd95a5c228d8781d4a000 Mon Sep 17 00:00:00 2001 From: Stefan Tjarks <66305+stj@users.noreply.github.com> Date: Thu, 18 Mar 2021 08:52:21 -0700 Subject: [PATCH 3/6] grammar --- ecs_logging/_stdlib.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/ecs_logging/_stdlib.py b/ecs_logging/_stdlib.py index 28413dc..cffa045 100644 --- a/ecs_logging/_stdlib.py +++ b/ecs_logging/_stdlib.py @@ -117,7 +117,7 @@ def _record_error_type(self, record): exc_info = record.exc_info if not exc_info: # exc_info is either an iterable or bool. If it doesn't - # evaluate to True, then no error type used. + # evaluate to True, then no error type is used. return None if isinstance(exc_info, bool): # if it is a bool, then look at sys.exc_info From 092c570721c066a7a9ce2b1fdd7f4cc43dabc71b Mon Sep 17 00:00:00 2001 From: Stefan Tjarks <66305+stj@users.noreply.github.com> Date: Thu, 18 Mar 2021 13:58:11 -0700 Subject: [PATCH 4/6] add missing import --- ecs_logging/_stdlib.py | 1 + 1 file changed, 1 insertion(+) diff --git a/ecs_logging/_stdlib.py b/ecs_logging/_stdlib.py index cffa045..a89abee 100644 --- a/ecs_logging/_stdlib.py +++ b/ecs_logging/_stdlib.py @@ -16,6 +16,7 @@ # under the License. import logging +import sys import time from traceback import format_tb from ._meta import ECS_VERSION From 3d0c7187a2397268ca8280bd2e404e3f82b0ece4 Mon Sep 17 00:00:00 2001 From: Seth Michael Larson Date: Mon, 5 Apr 2021 12:33:00 -0500 Subject: [PATCH 5/6] Update test_stdlib_formatter.py --- tests/test_stdlib_formatter.py | 1 + 1 file changed, 1 insertion(+) diff --git a/tests/test_stdlib_formatter.py b/tests/test_stdlib_formatter.py index e7f7f49..f0a3d32 100644 --- a/tests/test_stdlib_formatter.py +++ b/tests/test_stdlib_formatter.py @@ -195,6 +195,7 @@ def test_exc_info_false_does_not_raise(logger): ecs = json.loads(stream.getvalue().rstrip()) assert ecs["log.level"] == "info" assert ecs["message"] == "there was no error" + assert "error" not in ecs def test_stack_trace_limit_traceback(logger): From 19c9834515403268755b1f45d1476bfe87f4084a Mon Sep 17 00:00:00 2001 From: Colton Myers Date: Tue, 6 Jul 2021 10:35:20 -0600 Subject: [PATCH 6/6] CHANGELOG --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index c3bb16b..56fa6fb 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,7 @@ (used for the log `message`) and `event.dataset` (a field provided by the `elasticapm` integration) ([#46](https://github.com/elastic/ecs-logging-python/pull/46)) * Add default/fallback handling for json.dumps ([#47](https://github.com/elastic/ecs-logging-python/pull/47)) +* Fixed an issue in `StdLibFormatter` when `exc_info=False` ([#42](https://github.com/elastic/ecs-logging-python/pull/42)) ## 1.0.0 (2021-02-08)