Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Be more defensive about string interpolation #475

Merged
merged 1 commit into from
Nov 22, 2022
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
7 changes: 7 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,13 @@ You can find out backwards-compatibility policy [here](https://github.com/hynek/

## [Unreleased](https://github.com/hynek/structlog/compare/22.2.0...HEAD)

### Changed

- String interpolation in `FilteringBoundLogger` (used by default) is now only attempted if positional arguments are passed.
This prevents crashes if something different than a string is passed for the *event* argument.
[#475](https://github.com/hynek/structlog/pull/475)


## [22.2.0](https://github.com/hynek/structlog/compare/22.1.0...22.2.0) - 2022-11-19

### Deprecated
Expand Down
17 changes: 13 additions & 4 deletions src/structlog/_log_levels.py
Original file line number Diff line number Diff line change
Expand Up @@ -153,14 +153,20 @@ def make_method(
name = _LEVEL_TO_NAME[level]

def meth(self: Any, event: str, *args: Any, **kw: Any) -> Any:
if not args:
return self._proxy_to_logger(name, event, **kw)

return self._proxy_to_logger(name, event % args, **kw)

async def ameth(self: Any, event: str, *args: Any, **kw: Any) -> Any:
if args:
event = event % args

ctx = contextvars.copy_context()
await asyncio.get_running_loop().run_in_executor(
None,
lambda: ctx.run(
lambda: self._proxy_to_logger(name, event % args, **kw)
lambda: self._proxy_to_logger(name, event, **kw)
),
)

Expand All @@ -174,6 +180,9 @@ def log(self: Any, level: int, event: str, *args: Any, **kw: Any) -> Any:
return None
name = _LEVEL_TO_NAME[level]

if not args:
return self._proxy_to_logger(name, event, **kw)

return self._proxy_to_logger(name, event % args, **kw)

async def alog(
Expand All @@ -182,13 +191,13 @@ async def alog(
if level < min_level:
return None
name = _LEVEL_TO_NAME[level]
if args:
event = event % args

ctx = contextvars.copy_context()
return await asyncio.get_running_loop().run_in_executor(
None,
lambda: ctx.run(
lambda: self._proxy_to_logger(name, event % args, **kw)
),
lambda: ctx.run(lambda: self._proxy_to_logger(name, event, **kw)),
)

meths: dict[str, Callable[..., Any]] = {"log": log, "alog": alog}
Expand Down
60 changes: 60 additions & 0 deletions tests/test_log_levels.py
Original file line number Diff line number Diff line change
Expand Up @@ -61,6 +61,26 @@ async def test_async_one_below(self, bl, cl):

assert [] == cl.calls

def test_no_args(self, bl, cl):
"""
If no args are passed, don't attempt intepolation.

See also #473
"""
bl.info(42)

assert 42 == cl.calls[0][2]["event"]

async def test_async_no_args(self, bl, cl):
"""
If no args are passed, don't attempt intepolation.

See also #473
"""
await bl.ainfo(42)

assert 42 == cl.calls[0][2]["event"]

def test_log_exact_level(self, bl, cl):
"""
if log level is exactly the min_level, log.
Expand Down Expand Up @@ -93,6 +113,32 @@ async def test_alog_one_below(self, bl, cl):

assert [] == cl.calls

async def test_alog_no_args(self, bl, cl):
"""
If no args are passed, interpolation is not attempted.

See also #473
"""
await bl.alog(logging.INFO, 42)

assert 42 == cl.calls[0][2]["event"]

def test_log_interp(self, bl, cl):
"""
Interpolation happens if args are passed.
"""
bl.log(logging.INFO, "answer is %d.", 42)

assert "answer is 42." == cl.calls[0][2]["event"]

async def test_alog_interp(self, bl, cl):
"""
Interpolation happens if args are passed.
"""
await bl.alog(logging.INFO, "answer is %d.", 42)

assert "answer is 42." == cl.calls[0][2]["event"]

def test_filter_bound_below_missing_event_string(self, bl):
"""
Missing event arg causes exception below min_level.
Expand Down Expand Up @@ -149,6 +195,20 @@ async def test_async_exception_passed(self, bl, cl):

assert [("error", (), {"event": "boom", "exc_info": 42})] == cl.calls

def test_exception_pass_exception(self, bl, cl):
"""
If an Exception is passed for the event, don't explode.

Not a documented feature, but a regression for some people. See #473.
"""
try:
raise Exception("foo")
except Exception as e:
bl.exception(e)
exc = e

assert exc is cl.calls[0][2]["event"]

@pytest.mark.parametrize("level", tuple(_LEVEL_TO_NAME.keys()))
def test_pickle(self, level):
"""
Expand Down