From 2ab2b55bb76698647b6f9b5975b7cd6c2628cece Mon Sep 17 00:00:00 2001 From: Hynek Schlawack Date: Fri, 7 Oct 2022 10:15:32 +0200 Subject: [PATCH 1/3] Add string interpolation to FilteringBoundLogger --- .github/workflows/ci.yml | 2 ++ CHANGELOG.md | 12 ++++++++++ readthedocs.yml | 2 +- src/structlog/_log_levels.py | 4 ++-- src/structlog/types.py | 44 +++++++++++++++++++----------------- tests/test_log_levels.py | 8 +++++++ tox.ini | 2 +- typing_examples.py | 3 +++ 8 files changed, 52 insertions(+), 25 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 118b8aa9..0e8705a1 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -107,6 +107,7 @@ jobs: fail-fast: false matrix: python-version: + # mypy on 3.7 fails but there's nothing we can do about it - "3.8" - "3.9" - "3.10" @@ -128,6 +129,7 @@ jobs: - uses: actions/checkout@v3 - uses: actions/setup-python@v4 with: + # Keep in sync with tox.ini/docs & readthedocs.yml python-version: "3.10" - run: python -m pip install --upgrade wheel tox diff --git a/CHANGELOG.md b/CHANGELOG.md index a8550ee6..dc8f9a5d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -25,6 +25,18 @@ So please make sure to **always** properly configure your applications. Please use [`importlib.metadata`](https://docs.python.org/3.10/library/importlib.metadata.html) instead (for Python 3.7: the [*importlib-metadata*](https://pypi.org/project/importlib-metadata/) PyPI package). +### Added + +- `FilteringBoundLogger` (used by default) now allows for string interpolation using positional arguments: + + ```pycon + >>> log.info("Hello %s! The answer is %d.", "World", 42, x=1) + 2022-10-07 10:04.31 [info ] Hello World! The answer is 42. x=1 + ``` + + [#454](/~https://github.com/hynek/structlog/pull/454) + + ### Changed - The build backend has been switched to [*Hatch*](https://hatch.pypa.io/). diff --git a/readthedocs.yml b/readthedocs.yml index d335c40d..f563d645 100644 --- a/readthedocs.yml +++ b/readthedocs.yml @@ -5,7 +5,7 @@ formats: all build: os: ubuntu-20.04 tools: - # Keep version in sync with tox.ini (docs and gh-actions). + # Keep version in sync with tox.ini/docs and ci.yml/docs python: "3.10" python: diff --git a/src/structlog/_log_levels.py b/src/structlog/_log_levels.py index 4c1cb5c8..4882669d 100644 --- a/src/structlog/_log_levels.py +++ b/src/structlog/_log_levels.py @@ -126,8 +126,8 @@ def make_method(level: int) -> Callable[..., Any]: name = _LEVEL_TO_NAME[level] - def meth(self: Any, event: str, **kw: Any) -> Any: - return self._proxy_to_logger(name, event, **kw) + def meth(self: Any, event: str, *args: Any, **kw: Any) -> Any: + return self._proxy_to_logger(name, event % args, **kw) meth.__name__ = name diff --git a/src/structlog/types.py b/src/structlog/types.py index adc840c7..65542dea 100644 --- a/src/structlog/types.py +++ b/src/structlog/types.py @@ -151,6 +151,8 @@ class FilteringBoundLogger(BindableLogger, Protocol): The only way to instantiate one is using `make_filtering_bound_logger`. .. versionadded:: 20.2.0 + .. versionadded:: 22.2.0 + String interpolation using positional arguments. """ def bind(self, **new_values: Any) -> FilteringBoundLogger: @@ -181,53 +183,53 @@ def new(self, **new_values: Any) -> FilteringBoundLogger: .. versionadded:: 22.1.0 """ - def debug(self, event: str, **kw: Any) -> Any: + def debug(self, event: str, *args: Any, **kw: Any) -> Any: """ - Log *event* with **kw** at **debug** level. + Log ``event % args`` with **kw** at **debug** level. """ - def info(self, event: str, **kw: Any) -> Any: + def info(self, event: str, *args: Any, **kw: Any) -> Any: """ - Log *event* with **kw** at **info** level. + Log ``event % args`` with **kw** at **info** level. """ - def warning(self, event: str, **kw: Any) -> Any: + def warning(self, event: str, *args: Any, **kw: Any) -> Any: """ - Log *event* with **kw** at **warn** level. + Log ``event % args`` with **kw** at **warn** level. """ - def warn(self, event: str, **kw: Any) -> Any: + def warn(self, event: str, *args: Any, **kw: Any) -> Any: """ - Log *event* with **kw** at **warn** level. + Log ``event % args`` with **kw** at **warn** level. """ - def error(self, event: str, **kw: Any) -> Any: + def error(self, event: str, *args: Any, **kw: Any) -> Any: """ - Log *event* with **kw** at **error** level. + Log ``event % args`` with **kw** at **error** level. """ - def err(self, event: str, **kw: Any) -> Any: + def err(self, event: str, *args: Any, **kw: Any) -> Any: """ - Log *event* with **kw** at **error** level. + Log ``event % args`` with **kw** at **error** level. """ - def fatal(self, event: str, **kw: Any) -> Any: + def fatal(self, event: str, *args: Any, **kw: Any) -> Any: """ - Log *event* with **kw** at **critical** level. + Log ``event % args`` with **kw** at **critical** level. """ - def exception(self, event: str, **kw: Any) -> Any: + def exception(self, event: str, *args: Any, **kw: Any) -> Any: """ - Log *event* with **kw** at **error** level and ensure that ``exc_info`` - is set in the event dictionary. + Log ``event % args`` with **kw** at **error** level and ensure that + ``exc_info`` is set in the event dictionary. """ - def critical(self, event: str, **kw: Any) -> Any: + def critical(self, event: str, *args: Any, **kw: Any) -> Any: """ - Log *event* with **kw** at **critical** level. + Log ``event % args`` with **kw** at **critical** level. """ - def msg(self, event: str, **kw: Any) -> Any: + def msg(self, event: str, *args: Any, **kw: Any) -> Any: """ - Log *event* with **kw** at **info** level. + Log ``event % args`` with **kw** at **info** level. """ diff --git a/tests/test_log_levels.py b/tests/test_log_levels.py index 42528876..509a485b 100644 --- a/tests/test_log_levels.py +++ b/tests/test_log_levels.py @@ -103,3 +103,11 @@ def test_pickle(self, level): bl = make_filtering_bound_logger(level) assert bl == pickle.loads(pickle.dumps(bl)) + + def test_pos_args(self, bl, cl): + """ + Positional arguments are used for string interpolation. + """ + bl.info("hello %s -- %d!", "world", 42) + + assert [("info", (), {"event": "hello world -- 42!"})] == cl.calls diff --git a/tox.ini b/tox.ini index adb22da3..f2ad31b6 100644 --- a/tox.ini +++ b/tox.ini @@ -5,7 +5,7 @@ ignore = E203,W503,W504 # We don't run pre-commit in CI, because we use pre-commit.ci. [gh-actions] python = - 3.7: py37 # mypy on 3.7 fails but there's nothing we can do about it + 3.7: py37 3.8: py38 3.9: py39 3.10: py310 diff --git a/typing_examples.py b/typing_examples.py index 6e8b5b75..8ccdec9e 100644 --- a/typing_examples.py +++ b/typing_examples.py @@ -310,3 +310,6 @@ def typecheck_filtering_return() -> None: structlog.processors.JSONRenderer(), ] ) + +fbl: FilteringBoundLogger = structlog.get_logger() +fbl.info("Hello %s! The answer is %d.", "World", 42, x=1) From b3a45b4169e64f0f8c3b3f5235b2c8f0f3da3763 Mon Sep 17 00:00:00 2001 From: Hynek Schlawack Date: Fri, 7 Oct 2022 10:44:48 +0200 Subject: [PATCH 2/3] Add to getting started --- docs/getting-started.md | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/docs/getting-started.md b/docs/getting-started.md index 06ddc5b5..b30ca076 100644 --- a/docs/getting-started.md +++ b/docs/getting-started.md @@ -27,8 +27,8 @@ And indeed, the simplest possible usage looks like this >>> import structlog >>> log = structlog.get_logger() - >>> log.info("greeted", whom="world", more_than_a_string=[1, 2, 3]) # doctest: +SKIP - 2022-09-11 11:58.26 [info ] greeted more_than_a_string=[1, 2, 3] whom=world + >>> log.info("hello, %s!", "world", key="value!", more_than_strings=[1, 2, 3]) # doctest: +SKIP + 2022-10-07 10:41.29 [info ] hello, world! key=value! more_strings=[1, 2, 3] ``` Here, `structlog` takes full advantage of its hopefully useful default settings: @@ -36,6 +36,9 @@ Here, `structlog` takes full advantage of its hopefully useful default settings: - Output is sent to [standard out] instead of exploding into the user's face or doing nothing. - It imitates standard library `logging`'s log levels for familiarity -- even if you're not using any of your integrations. By default, no level-based filtering is done, but it comes with a very fast filtering machinery in the form of `structlog.make_filtering_bound_logger()`. +- Like `logging`, positional arguments are [interpolated into the message string using %](https://docs.python.org/3/library/stdtypes.html#old-string-formatting). + That might look dated, but it's *much* faster than using {any}`str.format` and allows ``structlog`` to be used as drop-in replacement for {mod}`logging` in more cases. + If you *know* that the log entry is *always* gonna be logged out, just use [f-strings](https://docs.python.org/3/tutorial/inputoutput.html#formatted-string-literals) which are the fastest. - All keywords are formatted using `structlog.dev.ConsoleRenderer`. That in turn uses `repr` to serialize all values to strings. Thus, it's easy to add support for logging of your own objects[^prod-json]. From 364848e112f22c47cb195da7b42927140995afbb Mon Sep 17 00:00:00 2001 From: Hynek Schlawack Date: Mon, 10 Oct 2022 07:20:53 +0200 Subject: [PATCH 3/3] Mention interpolation in why --- docs/why.rst | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) diff --git a/docs/why.rst b/docs/why.rst index 48ea1c53..8d399203 100644 --- a/docs/why.rst +++ b/docs/why.rst @@ -31,10 +31,18 @@ You can stop writing prose and start thinking in terms of an event that happens >>> from structlog import get_logger >>> log = get_logger() >>> log.info("key_value_logging", out_of_the_box=True, effort=0) - 2020-11-18 09:17.09 [info ] key_value_logging effort=0 out_of_the_box=True + 2020-11-18 09:17:09 [info ] key_value_logging effort=0 out_of_the_box=True Each log entry is a meaningful dictionary instead of an opaque string now! +That said, ``structlog`` is not taking anything away from you. +You can still use string interpolation: + +.. code-block:: pycon + + >>> log.info("Hello, %s!", "world") + 2022-10-10 07:19:25 [info ] Hello, world! + Data Binding ============ @@ -46,7 +54,7 @@ Since log entries are dictionaries, you can start binding and re-binding key/val >>> log = log.bind(user="anonymous", some_key=23) >>> log = log.bind(user="hynek", another_key=42) >>> log.info("user.logged_in", happy=True) - 2020-11-18 09:18.28 [info ] user.logged_in another_key=42 happy=True some_key=23 user=hynek + 2020-11-18 09:18:28 [info ] user.logged_in another_key=42 happy=True some_key=23 user=hynek You can also bind key/value pairs to :doc:`context variables ` that look global, but are local to your thread or *asyncio* context (i.e. often your request).