Skip to content

Commit

Permalink
Be more defensive about string interpolation
Browse files Browse the repository at this point in the history
Prevents assumptions about `event` being a string.

Fixes #473
  • Loading branch information
hynek committed Nov 22, 2022
1 parent 7cf81c3 commit d34af2a
Show file tree
Hide file tree
Showing 3 changed files with 79 additions and 4 deletions.
6 changes: 6 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,12 @@ 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.


## [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

0 comments on commit d34af2a

Please sign in to comment.