From 0d644c1b5f596b6fb358ff22c30f7f3f6dca7c33 Mon Sep 17 00:00:00 2001 From: upstream Date: Fri, 4 Sep 2026 08:12:57 +0200 Subject: [PATCH] Upstream hynek/structlog state of the touched files before 6c697cd1f1 --- CHANGELOG.md | 1149 ++++++++++++++++++++++++++ src/structlog/stdlib.py | 1258 +++++++++++++++++++++++++++++ tests/test_stdlib.py | 1693 +++++++++++++++++++++++++++++++++++++++ 3 files changed, 4100 insertions(+) create mode 100644 CHANGELOG.md create mode 100644 src/structlog/stdlib.py create mode 100644 tests/test_stdlib.py diff --git a/CHANGELOG.md b/CHANGELOG.md new file mode 100644 index 0000000..b23d71a --- /dev/null +++ b/CHANGELOG.md @@ -0,0 +1,1149 @@ +# Changelog + +All notable changes to this project will be documented in this file. + +The format is based on [Keep a Changelog](https://keepachangelog.com/) and this project adheres to [Calendar Versioning](https://calver.org/). + +The **first number** of the version is the year. +The **second number** is incremented with each release, starting at 1 for each year. +The **third number** is for emergencies when we need to start branches for older releases. + +You can find our backwards-compatibility policy [here](https://github.com/hynek/structlog/blob/main/.github/SECURITY.md). + + + + +## [Unreleased](https://github.com/hynek/structlog/compare/26.1.0...HEAD) + + +## [26.1.0](https://github.com/hynek/structlog/compare/25.5.0...26.1.0) - 2026-06-06 + +### Removed + +- Python 3.8 and 3.9 support. + + +### Deprecated + +- Support for *better-exceptions* is deprecated and will be removed within a year. + Use our Rich integration or copy-paste the [one line of code you need](https://github.com/hynek/structlog/blob/2c059a0dc029d9370e1e4a6e9683063205bbb68f/src/structlog/dev.py#L488-L498). + [#802](https://github.com/hynek/structlog/pull/802) + + +### Added + +- Python 3.15 support. + [#813](https://github.com/hynek/structlog/pull/813) + +- `structlog.dev.rich_monochrome_traceback` for Rich-based monochrome exception rendering and add support for it throughout `structlog.dev.ConsoleRenderer` when the user asks for no colors. + [#794](https://github.com/hynek/structlog/pull/794) + +- `structlog.BytesLogger` now has a `name` attribute which allows you to use it with the `structlog.stdlib.add_logger_name()` processor *without* using the standard library integration. + [#786](https://github.com/hynek/structlog/pull/786) + +- `structlog.processors.CallsiteParameterAdder` now supports `CallsiteParameter.QUAL_MODULE` that adds the qualified import name of the module of the callsite, or `__main__` if the module is the entry point. + This is only available for *structlog*-originated events since the standard library has no equivalent (except for the convention of setting the logger's name to `__name__`). + [#812](https://github.com/hynek/structlog/pull/812) + +- `structlog.stdlib.BoundLogger` now has `is_enabled_for()` and `get_effective_level()` methods that are snake_case aliases for its `isEnabledFor()` and `getEffectiveLevel()` methods. + This makes it more compatible with the native `structlog.typing.FilteringBoundLogger`, so you can swap configurations without changing your call sites. + [#818](https://github.com/hynek/structlog/pull/818) + + +### Changed + +- `structlog.dev.ConsoleRenderer` does not warn anymore when the `exception` key has a rendered value despite having a fancy formatter configured. + [#790](https://github.com/hynek/structlog/pull/790) + + +### Fixed + +- `structlog.BytesLogger`, `structlog.PrintLogger`, and `structlog.WriteLogger` now hold *weak* references to the files they use for output. + This prevents their leakage in long-running processes that open many logfiles, such as task executors that create a per-task `BytesLogger` or `WriteLogger`. + [#807](https://github.com/hynek/structlog/pull/807) + +- `structlog.WriteLogger` is usable after unpickling. + [#787](https://github.com/hynek/structlog/pull/787) + +- `structlog.processors.CallsiteParameterAdder` now reports the calling thread's id and name for async log methods, instead of the thread from the executor pool that runs the underlying sync logger. + [#710](https://github.com/hynek/structlog/issues/710) + [#805](https://github.com/hynek/structlog/pull/805) + + +## [25.5.0](https://github.com/hynek/structlog/compare/25.4.0...25.5.0) - 2025-10-27 + +### Deprecated + +- `structlog.dev.ConsoleRenderer()`'s *pad_event* argument has been renamed to *pad_event_to* to differentiate it from the boolean *pad_level* argument. + *pad_event* is now deprecated. + + +### Added + +- Added `structlog.dev.ConsoleRenderer.get_active()` that returns the currently active `structlog.dev.ConsoleRenderer()`. + [#749](https://github.com/hynek/structlog/pull/749) + +- `structlog.dev.ConsoleRenderer()` now supports setting the `exception_formatter` attribute. + + You can now disable the pretty-printing of exceptions by setting it to `structlog.dev.plain_traceback`: + + ```python + cr = structlog.dev.ConsoleRenderer.get_active() + cr.exception_formatter = structlog.dev.plain_traceback + ``` + + Same goes for *sort_keys*, *columns*, *colors*, *force_colors*, *level_styles*, *pad_event_to*, *event_key*, *timestamp_key*, and *repr_native_str*. + + [#749](https://github.com/hynek/structlog/pull/749) + [#756](https://github.com/hynek/structlog/pull/756) + [#757](https://github.com/hynek/structlog/pull/757) + [#759](https://github.com/hynek/structlog/pull/759) + +- Added `structlog.dev.ConsoleRenderer.get_default_column_styles()` for reuse the default column styles. + [#741](https://github.com/hynek/structlog/pull/741) + +- `structlog.testing.capture_logs()` now optionally accepts *processors* to apply before capture. + [#728](https://github.com/hynek/structlog/pull/728) + +- `structlog.dev.RichTracebackFormatter` now exposes the upstream *code_width* parameter. + Default *width* is now `None` for full terminal width. + Full terminal width is now handled by Rich itself, bringing support for reflow and `COLUMN` environment variable. + Passing `-1` for *width* is now deprecated and automatically replaced by `None`. + [#717](https://github.com/hynek/structlog/pull/717) + +- Native loggers now allow the passing of a dictionary for dictionary-based interpolation `log.info("hello %(name)s!", {"name": "world"})`. + [#748](https://github.com/hynek/structlog/pull/748) + +- On Python 3.11+, `structlog.processors.CallsiteParameterAdder` now supports `CallsiteParameter.QUAL_NAME` that adds the qualified name of the callsite, including scope and class names. + This is only available for *structlog*-originated events since the standard library has no equivalent. + +- `structlog.stdlib.LoggerFactory` now supports the *stacklevel* parameter. + [#763](https://github.com/hynek/structlog/pull/763) + + +### Changed + +- `structlog.dev.rich_traceback()` now throws a more helpful error when Rich is missing. + [#735](https://github.com/hynek/structlog/pull/735) + + +### Fixed + +- `structlog.processors.MaybeTimeStamper` now respects the *key* argument when determining whether to overwrite the timestamp field. + [#747](https://github.com/hynek/structlog/pull/747) + +- `structlog.tracebacks.extract()` no longer raises a `RecursionError` when the cause chain of an exception contains itself. + [#739](https://github.com/hynek/structlog/pull/739) + +- Default config now respects `FORCE_COLOR` on Windows. + [#758](https://github.com/hynek/structlog/pull/758) + + +## [25.4.0](https://github.com/hynek/structlog/compare/25.3.0...25.4.0) - 2025-06-02 + +### Added + +- Support for Python 3.14 and Python 3.13.4. + + Python 3.14 has an backwards-incompatible change to `logging.Logger.isEnabledFor()` (it now always returns False if a log entry is in flight) that has been backported to 3.13.4 (expected on 2025-06-03). + It mainly affects `structlog.stdlib.filter_by_level()`. + [#723](https://github.com/hynek/structlog/pull/723) + +- `structlog.tracebacks` now handles [exception groups](https://docs.python.org/3/library/exceptions.html#exception-groups). + `structlog.tracebacks.Stack` has two new fields, `is_group: bool` and `exceptions: list[Trace]`. + This works similarly to what Rich v14.0.0 does. + [#720](https://github.com/hynek/structlog/pull/720) + + +### Fixed + +- `structlog.processors.ExceptionPrettyPrinter` now respects the *exception_formatter* arguments instead of always using the default formatter. + [#724](https://github.com/hynek/structlog/pull/724) + + +## [25.3.0](https://github.com/hynek/structlog/compare/25.2.0...25.3.0) - 2025-04-25 + +### Fixed + +- `structlog.processors.TimeStamper` now again uses timestamps using UTC for custom format strings when `utc=True`. + [#713](https://github.com/hynek/structlog/pull/713) + + +## [25.2.0](https://github.com/hynek/structlog/compare/25.1.0...25.2.0) - 2025-03-11 + +### Added + +- `structlog.tracebacks.Stack` now includes an `exc_notes` field reflecting the notes attached to the exception. + [#684](https://github.com/hynek/structlog/pull/684) + + +### Changed + +- `structlog.stdlib.BoundLogger`'s binding-related methods now also return `Self`. + [#694](https://github.com/hynek/structlog/pull/694) + +- `structlog.processors.TimeStamper` now produces internally timezone-aware `datetime` objects. + Default output hasn't changed, but you can now use `%z` in your *fmt* string. + [#709](https://github.com/hynek/structlog/pull/709) + + +### Fixed + +- Expose `structlog.dev.RichTracebackFormatter` for imports. + [#699](https://github.com/hynek/structlog/pull/699) +- Expose `structlog.processors.LogfmtRenderer` for imports. + [#701](https://github.com/hynek/structlog/pull/701) + +## [25.1.0](https://github.com/hynek/structlog/compare/24.4.0...25.1.0) - 2025-01-16 + +### Added + +- Add `structlog.stdlib.render_to_log_args_and_kwargs` processor. + Same as `structlog.stdlib.render_to_log_kwargs`, but also allows to pass positional arguments to `logging`. + With it, you do not need to add `structlog.stdlib.PositionalArgumentsFormatter` processor to format positional arguments from *structlog* loggers. + [#668](https://github.com/hynek/structlog/pull/668) + +- Native loggers now have `is_enabled_for()` and `get_effective_level()` methods that mirror the behavior of the standard library's `logging.Logger.isEnabledFor()` and `logging.Logger.getEffectiveLevel()`. + [#689](https://github.com/hynek/structlog/pull/689) + + +### Changed + +- `structlog.typing.BindableLogger` protocol now returns `Self` instead of `BindableLogger`. + This adds a dependency on [*typing-extensions*](https://pypi.org/project/typing-extensions/) for Pythons older than 3.11. + [#642](https://github.com/hynek/structlog/pull/642) + [#659](https://github.com/hynek/structlog/pull/659) + +- `structlog.dev.ConsoleRenderer` will quote string value with special characters. + [#647](https://github.com/hynek/structlog/pull/647) + +- `structlog.stdlib.recreate_defaults()` now also adds `structlog.stdlib.PositionalArgumentsFormatter`. + In default native mode, this is done by the loggers at the edge. + +- `structlog.make_filtering_bound_logger()` now also accepts a string for *min_level*. + + +### Fixed + +- Fix handling calls to `{logger}.exception()` outside of exception blocks. + Depending on the structlog configuration, + this either resulted in an event dict key `exception: "MISSING"` or lead to an error. + Now, an invalid or missing `exc_info` will just be ignored. + This means, that calling `{logger}.exception()` outside of an exception block is basically the same as calling `{logger}.error()`. + [#634](https://github.com/hynek/structlog/issues/634) + [#680](https://github.com/hynek/structlog/pull/680) + +- Instantiating `structlog.dev.ConsoleRenderer` does not mutate the passed *styles* dict anymore. + [#669](https://github.com/hynek/structlog/pull/669) + +- The native `FilteringBoundLogger.fatal()` method now maps to the critical level, as it does in the standard library. + Note that the level is discouraged to use there, so we recommend to stick to `error()` or `critical()`. + [#677](https://github.com/hynek/structlog/pull/677) + +- `structlog.tracebacks.ExceptionDictTransformer` now actually accepts `None` for `locals_max_length` and `locals_max_string`. + [#675](https://github.com/hynek/structlog/pull/675) + + +## [24.4.0](https://github.com/hynek/structlog/compare/24.3.0...24.4.0) - 2024-07-17 + +### Changed + +No code changes since 24.3.0 + + +## [24.3.0](https://github.com/hynek/structlog/compare/24.2.0...24.3.0) - 2024-07-17 + +### Added + +- Restore feature parity between `structlog.traceback.ExceptionDictTransformer` and Rich's traceback extractor: + + - When displaying locals, use Rich for formatting if it is available. + - When displaying locals, call `repr()` on strings, too (improves handling of `SecretStr` implementations). + - Add `locals_max_length` config option + - Add `locals_hide_sunder` config option + - Add `locals_hide_dunder` config option + - Add `suppress` config option + + [#627](https://github.com/hynek/structlog/pull/627) + + +### Changed + +- `structlog.testing.capture_logs()` now maps the `exception` log level to `error` (as it's elsewhere). + [#628](https://github.com/hynek/structlog/pull/628) + + +## [24.2.0](https://github.com/hynek/structlog/compare/24.1.0...24.2.0) - 2024-05-27 + +### Added + +- It is now possible to disable log level-padding in `structlog.dev.LogLevelColumnFormatter` and `structlog.dev.ConsoleRenderer`. + [#599](https://github.com/hynek/structlog/pull/599) + +- The `structlog.processors.CallsiteParameterAdder` can now be pickled. + [#603](https://github.com/hynek/structlog/pull/603) + +- `structlog.processors.CallsiteParameterAdder` now also works with `structlog.stdlib.BoundLogger`'s non-standard async methods (`ainfo()`, and so forth) + [#618](https://github.com/hynek/structlog/pull/618) + + +### Changed + +- `structlog.processors.LogfmtRenderer` now escapes newlines. + [#592](https://github.com/hynek/structlog/pull/592) + +- `structlog.processors.LogfmtRenderer` now escapes backslashes and double quotes. + [#594](https://github.com/hynek/structlog/pull/594) + +- `structlog.processors.CallsiteParameterAdder` has been optimized to be about 2x faster. + [#606](https://github.com/hynek/structlog/pull/606) + + +### Fixed + +- `structlog.stdlib.render_to_log_kwargs` now correctly passes stacklevel as a kwarg to stdlib logging. + [#619](https://github.com/hynek/structlog/pull/620) + + + +## [24.1.0](https://github.com/hynek/structlog/compare/23.3.0...24.1.0) - 2024-01-08 + +### Fixed + +- The lazy logger proxy returned by `structlog.get_logger()` now returns its initial values when asked for context. + When asked for context before binding for the first time, it returned an empty dictionary in 23.3.0. + +- The displayed level name when using `structlog.stdlib.BoundLogger.exception()` is `"error"` instead of `"exception"`. + Fixes regression in 23.3.0. + [#584](https://github.com/hynek/structlog/issues/584) + +- Don't ignore the `width` argument of `RichTracebackFormatter`. + [#587](https://github.com/hynek/structlog/issues/587) + + +## [23.3.0](https://github.com/hynek/structlog/compare/23.2.0...23.3.0) - 2023-12-29 + +### Added + +- The colorful development logger is now even more configurable! + Choose freely your colors and the order of the key-value pairs! + Implement your own formatters for certain keys! + + Implementing the output on top of the new columns API has changed the default very slightly, but shouldn't be noticeable. + [#577](https://github.com/hynek/structlog/issues/577) + +- Async log methods (those starting with an `a`) now also support the collection of callsite information using `structlog.processors.CallsiteParameterAdder`. + [#565](https://github.com/hynek/structlog/issues/565) + + +### Changed + +- `structlog.stdlib.recreate_defaults()` now also adds `structlog.stdlib.add_logger_name` to the processors. + Check out the [updated screenshot](https://raw.githubusercontent.com/hynek/structlog/main/docs/_static/console_renderer.png)! + + +### Fixed + +- The return value from `get_logger()` (a `BoundLoggerLazyProxy`) now passes `isinstance`-checks against `structlog.typing.BindableLogger` on Python 3.12. + [#561](https://github.com/hynek/structlog/issues/561) + +- `structlog.threadlocal.tmp_bind()` now also works with `BoundLoggerLazyProxy` (in other words: before anything is bound to a bound logger). + +- stdlib: `ProcessorFormatter` can now be told to not render the log record message using `getMessage` and just `str(record.msg)` instead. + [#550](https://github.com/hynek/structlog/issues/550) + +- stdlib: `structlog.stdlib.BoundLogger.exception()`'s handling of`LogRecord.exc_info` is now set consistent with `logging`. + [#571](https://github.com/hynek/structlog/issues/571) + [#572](https://github.com/hynek/structlog/issues/572) + + +## [23.2.0](https://github.com/hynek/structlog/compare/23.1.0...23.2.0) - 2023-10-09 + +### Removed + +- Support for Python 3.7. + + +### Added + +- Official support for Python 3.12. + [#515](https://github.com/hynek/structlog/issues/515) + +- `structlog.processors.MaybeTimeStamper` that only adds a timestamp if there isn't one already. + [#81](https://github.com/hynek/structlog/issues/81) + +- `structlog.dev.ConsoleRenderer` now supports renamed timestamp keys using the *timestamp_key* parameter. + [#541](https://github.com/hynek/structlog/issues/541) + +- `structlog.dev.RichTracebackFormatter` that allows to configure the traceback formatting. + [#542](https://github.com/hynek/structlog/issues/542) + + +### Fixed + +- `FilteringBoundLogger.exception()` and `FilteringBoundLogger.aexception()` now support positional argument formatting like the rest of the methods. + [#531](https://github.com/hynek/structlog/issues/531) +- `structlog.processors.format_exc_info()` and `structlog.dev.ConsoleRenderer` do not crash anymore when told to format a non-existent exception. + [#533](https://github.com/hynek/structlog/issues/533) + + +## [23.1.0](https://github.com/hynek/structlog/compare/22.3.0...23.1.0) - 2023-04-06 + +### Added + +- `structlog.stdlib.BoundLogger` now has, analogously to our native logger, a full set of async log methods prefixed with an `a`: `await log.ainfo("event!")` + [#502](https://github.com/hynek/structlog/issues/502) + +- The default configuration now respects the presence of `FORCE_COLOR` (regardless of its value, unless an empty string). + This disables all heuristics whether it makes sense to use colors. + [#503](https://github.com/hynek/structlog/issues/503) + +- The default configuration now respects the presence of [`NO_COLOR`](https://no-color.org) (regardless of its value, unless an empty string). + This disables all heuristics whether it makes sense to use colors and overrides `FORCE_COLOR`. + [#504](https://github.com/hynek/structlog/issues/504) + + +### Fixed + +- ConsoleRenderer now reuses the `_figure_out_exc_info` to process the `exc_info` argument like `ExceptionRenderer` does. + This prevents crashes if the actual Exception is passed for the *exc_info* argument instead of a tuple or `True`. + [#482](https://github.com/hynek/structlog/issues/482) + +- `FilteringBoundLogger.aexception()` now extracts the exception info using `sys.exc_info()` before passing control to the asyncio executor (where original exception info is no longer available). + [#488](https://github.com/hynek/structlog/issues/488) + + +## [22.3.0](https://github.com/hynek/structlog/compare/22.2.0...22.3.0) - 2022-11-24 + +### 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) + + +### Fixed + +- String interpolation doesn't cause crashes in filtered log call anymore. + [#478](https://github.com/hynek/structlog/pull/478) + + +## [22.2.0](https://github.com/hynek/structlog/compare/22.1.0...22.2.0) - 2022-11-19 + +### Deprecated + +- Accessing package metadata as attributes on the *structlog* module is deprecated (for example, `structlog.__version__`). + 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). +- The `structlog.types` module is now deprecated in favor of the `structlog.typing` module. + It seems like the Python typing community is settling on this name. + + +### 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) + +- `FilteringBoundLogger` now also has support for *asyncio*-based logging. + Instead of a wrapper class like `structlog.stdlib.AsyncBoundLogger`, async equivalents have been added for all logging methods. + So instead of `log.info("hello")` you can also write `await log.ainfo("hello")` in async functions and methods. + + This seems like the better approach and if it's liked by the community, `structlog.stdlib.BoundLogger` will get those methods too. + [#457](https://github.com/hynek/structlog/pull/457) + + +### Changed + +- The documentation has been **heavily** overhauled. + Have a look if you haven't lately! + Especially the graphs in the [standard library chapter](https://www.structlog.org/en/latest/standard-library.html) have proven valuable to many. +- The build backend has been switched to [*Hatch*](https://hatch.pypa.io/). + + +### Fixed + +- The timestamps in the default configuration now use the correct separator (`:`) for seconds. + + +## [22.1.0](https://github.com/hynek/structlog/compare/21.5.0...22.1.0) - 2022-07-20 + +### Removed + +- Python 3.6 is not supported anymore. +- Pickling is now only possible with protocol version 3 and newer. + + +### Deprecated + +- The entire `structlog.threadlocal` module is deprecated. + Please use the primitives from `structlog.contextvars` instead. + + If you're using the modern APIs (`bind_threadlocal()` / `merge_threadlocal()`) it's enough to replace them 1:1 with their `contextvars` counterparts. + The old approach around `wrap_dict()` has been discouraged for a while. + + Currently there are no concrete plans to remove the module, but no patches against it will be accepted from now on. + [#409](https://github.com/hynek/structlog/pull/409) + + +### Added + +- `structlog.processors.StackInfoRenderer` now has an *additional_ignores* parameter that allows you to filter out your own logging layer. + [#396](https://github.com/hynek/structlog/issues/396) +- Added `structlog.WriteLogger`, a faster – but more low-level – alternative to `structlog.PrintLogger`. + It works the way `PrintLogger` used to work in previous versions. + [#403](https://github.com/hynek/structlog/pull/403) + [#404](https://github.com/hynek/structlog/pull/404) +- `structlog.make_filtering_bound_logger()`-returned loggers now also have a `log()` method to match the `structlog.stdlib.BoundLogger` signature closer. + [#413](https://github.com/hynek/structlog/pull/413) +- Added structured logging of tracebacks via the `structlog.tracebacks` module, + and most notably the `structlog.tracebacks.ExceptionDictTransformer` which can be used with the new `structlog.processors.ExceptionRenderer` to render JSON tracebacks. + [#407](https://github.com/hynek/structlog/pull/407) +- `structlog.stdlib.recreate_defaults(log_level=logging.NOTSET)` that recreates *structlog*'s defaults on top of standard library's `logging`. + It optionally also configures `logging` to log to standard out at the passed log level. + [#428](https://github.com/hynek/structlog/pull/428) +- `structlog.processors.EventRenamer` allows you to rename the hitherto hard-coded event dict key `event` to something else. + Optionally, you can rename another key to `event` at the same time, too. + So adding `EventRenamer(to="msg", replace_by="_event")` to your processor pipeline will rename the standard `event` key to `msg` and then rename the `_event` key to `event`. + This allows you to use the `event` key in your own log files and to have consistent log message keys across languages. +- `structlog.dev.ConsoleRenderer(event_key="event")` now allows to customize the name of the key that is used for the log message. + + +### Changed + +- `structlog.make_filtering_bound_logger()` now returns a method with the same signature for all log levels, whether they are active or not. + This ensures that invalid calls to inactive log levels are caught immediately and don't explode once the log level changes. + [#401](https://github.com/hynek/structlog/pull/401) +- `structlog.PrintLogger` – that is used by default – now uses `print()` for printing, making it a better citizen for interactive terminal applications. + [#399](https://github.com/hynek/structlog/pull/399) +- `structlog.testing.capture_logs` now works for already initialized bound loggers. + [#408](https://github.com/hynek/structlog/pull/412) +- `structlog.processors.format_exc_info()` is no longer a function, but an instance of `structlog.processors.ExceptionRenderer`. + Its behavior has not changed. + [#407](https://github.com/hynek/structlog/pull/407) +- The default configuration now includes the `structlog.contextvars.merge_contextvars` processor. + That means you can use [`structlog.contextvars`](https://www.structlog.org/en/stable/contextvars.html) features without configuring *structlog*. + + +### Fixed + +- Overloaded the `bind`, `unbind`, `try_unbind` and `new` methods in the `FilteringBoundLogger` [Protocol](https://docs.python.org/3/library/typing.html#typing.Protocol). + This makes it easier to use objects of type `FilteringBoundLogger` in a typed context. + [#392](https://github.com/hynek/structlog/pull/392) +- Monkeypatched `sys.stdout`s are now handled more gracefully by `ConsoleRenderer` (that's used by default). + [#404](https://github.com/hynek/structlog/pull/404) +- `structlog.stdlib.render_to_log_kwargs()` now correctly handles the presence of `exc_info`, `stack_info`, and `stackLevel` in the event dictionary. + They are transformed into proper keyword arguments instead of putting them into the `extra` dictionary. + [#424](https://github.com/hynek/structlog/issues/424), + [#427](https://github.com/hynek/structlog/issues/427) + + +## [21.5.0](https://github.com/hynek/structlog/compare/21.4.0...21.5.0) - 2021-12-16 + +### Added + +- Added the `structlog.processors.LogfmtRenderer` processor to render log lines using the [*logfmt*](https://brandur.org/logfmt) format. + [#376](https://github.com/hynek/structlog/pull/376) +- Added the `structlog.stdlib.ExtraAdder` processor that adds extra attributes of `logging.LogRecord` objects to the event dictionary. + This processor can be used for adding data passed in the `extra` parameter of the `logging` module's log methods to the event dictionary. + [#209](https://github.com/hynek/structlog/pull/209), + [#377](https://github.com/hynek/structlog/pull/377) +- Added the `structlog.processor.CallsiteParameterAdder` processor that adds parameters of the callsite that an event dictionary originated from to the event dictionary. + This processor can be used to enrich events dictionaries with information such as the function name, line number and filename that an event dictionary originated from. + [#380](https://github.com/hynek/structlog/pull/380) + + +## [21.4.0](https://github.com/hynek/structlog/compare/21.3.0...21.4.0) - 2021-11-25 + +### Added + +- Added the `structlog.threadlocal.bound_threadlocal` and `structlog.contextvars.bound_contextvars` decorator/context managers to temporarily bind key-value pairs to a thread-local and context-local context. + [#371](https://github.com/hynek/structlog/pull/371) + + +### Fixed + +- Fixed import when running in optimized mode (`PYTHONOPTIMIZE=2` or `python -OO`) +. + [#373](https://github.com/hynek/structlog/pull/373) + + +## [21.3.0](https://github.com/hynek/structlog/compare/21.2.0...21.3.0) - 2021-11-20 + +### Added + +- `structlog.dev.ConsoleRenderer` now has `sort_keys` boolean parameter that allows to disable the sorting of keys on output. + [#358](https://github.com/hynek/structlog/pull/358) + + +### Changed + +- *structlog* switched its packaging to [*flit*](https://flit.pypa.io/). + Users shouldn't notice a difference, but (re-)packagers might. +- `structlog.stdlib.AsyncBoundLogger` now determines the running loop when logging, not on instantiation. + That has a minor performance impact, but makes it more robust when loops change (for example, `aiohttp.web.run_app()`), or you want to use `sync_bl` *before* a loop has started. + + +### Fixed + +- `structlog.processors.TimeStamper` now works well with [*FreezeGun*](https://github.com/spulec/freezegun) even when it gets applied before the loggers are configured. + [#364](https://github.com/hynek/structlog/pull/364) + +- `structlog.stdlib.ProcessorFormatter` now has a *processors* argument that allows to define a processor chain to run over *all* log entries. + + Before running the chain, two additional keys are added to the event dictionary: `_record` and `_from_structlog`. + With them it's possible to extract information from `logging.LogRecord`s and differentiate between *structlog* and `logging` log entries while processing them. + + The old *processor* (singular) parameter is now deprecated, but no plans exist to remove it. + [#365](https://github.com/hynek/structlog/pull/365) + + +## [21.2.0](https://github.com/hynek/structlog/compare/21.1.0...21.2.0) - 2021-10-12 + +### Added + +- `structlog.threadlocal.get_threadlocal()` and `structlog.contextvars.get_contextvars()` can now be used to get a copy of the current thread-local/context-local context that has been bound using `structlog.threadlocal.bind_threadlocal()` and `structlog.contextvars.bind_contextvars()`. + [#331](https://github.com/hynek/structlog/pull/331), + [#337](https://github.com/hynek/structlog/pull/337) +- `structlog.threadlocal.get_merged_threadlocal(bl)` and `structlog.contextvars.get_merged_contextvars(bl)` do the same, but also merge the context from a bound logger *bl*. + Same pull requests as previous change. +- `structlog.contextvars.bind_contextvars()` now returns a mapping of keys to `contextvars.Token`s, allowing you to reset values using the new `structlog.contextvars.reset_contextvars()`. + [#339](https://github.com/hynek/structlog/pull/339) +- Exception rendering in `structlog.dev.ConsoleLogger` is now configurable using the `exception_formatter` setting. + If either the [Rich](https://github.com/Textualize/rich) or the [*better-exceptions*](https://github.com/qix-/better-exceptions) package is present, *structlog* will use them for pretty-printing tracebacks. + Rich takes precedence over *better-exceptions* if both are present. + + This only works if `format_exc_info` is **absent** in the processor chain. + [#330](https://github.com/hynek/structlog/pull/330), + [#349](https://github.com/hynek/structlog/pull/349) +- The final processor can now return a `bytearray` (additionally to `str` and `bytes`). + [#344](https://github.com/hynek/structlog/issues/344) + + +### Changed + +- To implement pretty exceptions (see Changes below), `structlog.dev.ConsoleRenderer` now formats exceptions itself. + + Make sure to remove `format_exc_info` from your processor chain if you configure *structlog* manually. + This change is not really breaking, because the old use-case will keep working as before. + However if you pass `pretty_exceptions=True` (which is the default if either `rich` or `better-exceptions` is installed), a warning will be raised and the exception will be rendered without prettification. +- All use of [Colorama](https://github.com/tartley/colorama) on non-Windows systems has been excised. + Thus, colors are now enabled by default in `structlog.dev.ConsoleRenderer` on non-Windows systems. + You can keep using Colorama to customize colors, of course. + [#345](https://github.com/hynek/structlog/pull/345) + + +### Fixed + +- *structlog* is now importable if `sys.stdout` is `None` (for example, when running using `pythonw`). [#313](https://github.com/hynek/structlog/issues/313) + + +## [21.1.0](https://github.com/hynek/structlog/compare/20.2.0...21.1.0) - 2021-02-18 + +### Changed + +- `structlog.dev.ConsoleRenderer` will now look for a `logger_name` key if no `logger` key is set. + [#295](https://github.com/hynek/structlog/pull/295) + + +### Fixed + +- `structlog.threadlocal.wrap_dict()` now has a correct type annotation. + [#290](https://github.com/hynek/structlog/pull/290) +- Fix isolation in `structlog.contextvars`. + [#302](https://github.com/hynek/structlog/pull/302) +- The default configuration and loggers are pickleable again. + [#301](https://github.com/hynek/structlog/pull/301) + + +## [20.2.0](https://github.com/hynek/structlog/compare/20.1.0...20.2.0) - 2020-12-31 + +### Removed + +- Python 2.7 and 3.5 aren't supported anymore. + The package meta data should ensure that you keep getting 20.1.0 on those versions. + [#244](https://github.com/hynek/structlog/pull/244) + + +### Deprecated + +- Accessing the `_context` attribute of a bound logger is now deprecated. + Please use the new `structlog.get_context()`. + + +### Added + +- *structlog* has now type hints for all of its APIs! + Since *structlog* is highly dynamic and configurable, this led to a few concessions like a specialized `structlog.stdlib.get_logger()` whose only difference to `structlog.get_logger()` is that it has the correct type hints. + + We consider them provisional for the time being – that means the backwards-compatibility does not apply to them in its full strength until we feel we got it right. + Please feel free to provide feedback! + [#223](https://github.com/hynek/structlog/issues/223), + [#282](https://github.com/hynek/structlog/issues/282) +- Added `structlog.make_filtering_logger` that can be used like `configure(wrapper_class=make_filtering_bound_logger(logging.INFO))`. + It creates a highly optimized bound logger whose inactive methods only consist of a `return None`. + This is now also the default logger. +- As a complement, `structlog.stdlib.add_log_level()` can now additionally be imported as `structlog.processors.add_log_level` since it just adds the method name to the event dict. +- Added `structlog.BytesLogger` to avoid unnecessary encoding round trips. + Concretely this is useful with *orjson* which returns bytes. + [#271](https://github.com/hynek/structlog/issues/271) +- The final processor now also may return bytes that are passed untouched to the wrapped logger. +- `structlog.get_context()` allows you to retrieve the original context of a bound logger. [#266](https://github.com/hynek/structlog/issues/266), +- Added `structlog.testing.CapturingLogger` for more unit testing goodness. +- Added `structlog.stdlib.AsyncBoundLogger` that executes logging calls in a thread executor and therefore doesn't block. + [#245](https://github.com/hynek/structlog/pull/245) + + +### Changed + +- The default bound logger (`wrapper_class`) if you don't configure *structlog* has changed. + It's mostly compatible with the old one but a few uncommon methods like `log`, `failure`, or `err` don't exist anymore. + + You can regain the old behavior by using `structlog.configure(wrapper_class=structlog.BoundLogger)`. + + Please note that due to the various interactions between settings, it's possible that you encounter even more errors. + We **strongly** urge you to always configure all possible settings since the default configuration is *not* covered by our backwards-compatibility policy. +- `structlog.processors.add_log_level()` is now part of the default configuration. +- `structlog.stdlib.ProcessorFormatter` no longer uses exceptions for control flow, allowing `foreign_pre_chain` processors to use `sys.exc_info()` to access the real exception. + + +### Fixed + +- `structlog.PrintLogger` now supports `copy.deepcopy()`. + [#268](https://github.com/hynek/structlog/issues/268) + + +## [20.1.0](https://github.com/hynek/structlog/compare/19.2.0...20.1.0) - 2020-01-28 + +### Deprecated + +- This is the last version to support Python 2.7 (including PyPy) and 3.5. + All following versions will only support Python 3.6 or later. + + +### Added + +- Added a new module `structlog.contextvars` that allows to have a global but context-local *structlog* context the same way as with `structlog.threadlocal` since 19.2.0. + [#201](https://github.com/hynek/structlog/issues/201), + [#236](https://github.com/hynek/structlog/pull/236) +- Added a new module `structlog.testing` for first class testing support. + The first entry is the context manager `capture_logs()` that allows to make assertions about structured log calls. + [#14](https://github.com/hynek/structlog/issues/14), + [#234](https://github.com/hynek/structlog/pull/234) +- Added `structlog.threadlocal.unbind_threadlocal()`. + [#239](https://github.com/hynek/structlog/pull/239) + + +### Fixed + +- The logger created by `structlog.get_logger()` is not detected as an abstract method anymore, when attached to an abstract base class. + [#229](https://github.com/hynek/structlog/issues/229) +- Colorama isn't initialized lazily on Windows anymore because it breaks rendering. + [#232](https://github.com/hynek/structlog/issues/232), + [#242](https://github.com/hynek/structlog/pull/242) + + +## [19.2.0](https://github.com/hynek/structlog/compare/19.1.0...19.2.0) - 2019-10-16 + +### Removed + +- Python 3.4 is not supported anymore. +It has been unsupported by the Python core team for a while now and its PyPI downloads are negligible. + + It's very unlikely that *structlog* will break under 3.4 anytime soon, but we don't test it anymore. + + +### Added + +- Full Python 3.8 support for `structlog.stdlib`. +- Added more pass-through properties to `structlog.stdlib.BoundLogger`. To makes it easier to use it as a drop-in replacement for `logging.Logger`. + [#198](https://github.com/hynek/structlog/issues/198) +- Added new processor `structlog.dev.set_exc_info()` that will set `exc_info=True` if the method's name is `exception` and `exc_info` isn't set at all. + *This is only necessary when the standard library integration is not used*. + It fixes the problem that in the default configuration, `structlog.get_logger().exception("hi")` in an `except` block would not print the exception without passing `exc_info=True` to it explicitly. + [#130](https://github.com/hynek/structlog/issues/130), + [#173](https://github.com/hynek/structlog/issues/173), + [#200](https://github.com/hynek/structlog/issues/200), + [#204](https://github.com/hynek/structlog/issues/204) +- Added a new thread-local API that allows binding values to a thread-local context explicitly without affecting the default behavior of `bind()`. + [#222](https://github.com/hynek/structlog/issues/222), + [#225](https://github.com/hynek/structlog/issues/225) +- Added *pass_foreign_args* argument to `structlog.stdlib.ProcessorFormatter`. It allows to pass a foreign log record's *args* attribute to the event dictionary under the `positional_args` key. + [#228](https://github.com/hynek/structlog/issues/228) + + + +### Changed + +- `structlog.stdlib.ProcessorFormatter` now takes a logger object as an optional keyword argument. + This makes `ProcessorFormatter` work properly with `stuctlog.stdlib.filter_by_level()`. + [#219](https://github.com/hynek/structlog/issues/219) +- `structlog.dev.ConsoleRenderer` now calls `str()` on the event value. [#221](https://github.com/hynek/structlog/issues/221) + + +### Fixed + +- `structlog.dev.ConsoleRenderer` now uses no colors by default, if Colorama is not available. + [#215](https://github.com/hynek/structlog/issues/215) +- `structlog.dev.ConsoleRenderer` now initializes Colorama lazily, to prevent accidental side-effects just by importing *structlog*. + [#210](https://github.com/hynek/structlog/issues/210) +- A best effort has been made to make as much of *structlog* pickleable as possible to make it friendlier with `multiprocessing` and similar libraries. + Some classes can only be pickled on Python 3 or using the [dill](https://pypi.org/project/dill/) library though and that is very unlikely to change. + + So far, the configuration proxy, `structlog.processor.TimeStamper`, `structlog.BoundLogger`, `structlog.PrintLogger` and `structlog.dev.ConsoleRenderer` have been made pickleable. + Please report if you need any another class fixed. + [#126](https://github.com/hynek/structlog/issues/126) + + +## [19.1.0](https://github.com/hynek/structlog/compare/18.2.0...19.1.0) - 2019-02-02 + +### Added + +- `structlog.ReturnLogger` and `structlog.PrintLogger` now have a `fatal()` log method. + [#181](https://github.com/hynek/structlog/issues/181) + + +### Changed + +- As announced in 18.1.0, `pip install -e .[dev]` now installs all development dependencies. + Sorry for the inconveniences this undoubtedly will cause! +- *structlog* now tolerates passing through `dict`s to stdlib logging. + [#187](https://github.com/hynek/structlog/issues/187), + [#188](https://github.com/hynek/structlog/pull/188), + [#189](https://github.com/hynek/structlog/pull/189) + + +### Fixed + +- Under certain (rather unclear) circumstances, the frame extraction could throw an `SystemError: error return without exception set`. + A workaround has been added. + [#174](https://github.com/hynek/structlog/issues/174) + + +## [18.2.0](https://github.com/hynek/structlog/compare/18.1.0...18.2.0) - 2018-09-05 + +### Added + +- Added `structlog.stdlib.add_log_level_number()` processor that adds the level *number* to the event dictionary. + Can be used to simplify log filtering. + [#151](https://github.com/hynek/structlog/pull/151) +- `structlog.processors.JSONRenderer` now allows for overwriting the *default* argument of its serializer. + [#77](https://github.com/hynek/structlog/pull/77), + [#163](https://github.com/hynek/structlog/pull/163) +- Added `try_unbind()` that works like `unbind()` but doesn't raise a `KeyError` if one of the keys is missing. + [#171](https://github.com/hynek/structlog/pull/171) + + +## [18.1.0](https://github.com/hynek/structlog/compare/17.2.0...18.1.0) - 2018-01-27 + +### Deprecated + +- The meaning of the `structlog[dev]` installation target will change from "colorful output" to "dependencies to develop *structlog*" in 19.1.0. + + The main reason behind this decision is that it's impossible to have a *structlog* in your normal dependencies and additionally a `structlog[dev]` for development (`pip` will report an error). + + +### Added + +- `structlog.dev.ConsoleRenderer` now accepts a *force_colors* argument to output colored logs even if the destination is not a tty. + Use this option if your logs are stored in files that are intended to be streamed to the console. +- `structlog.dev.ConsoleRenderer` now accepts a *level_styles* argument for overriding the colors for individual levels, as well as to add new levels. + See the docs for `ConsoleRenderer.get_default_level_styles()` for usage. + [#139](https://github.com/hynek/structlog/pull/139) +- Added `structlog.is_configured()` to check whether or not *structlog* has been configured. +- Added `structlog.get_config()` to introspect current configuration. + + +### Changed + +- Empty strings are valid events now. + [#110](https://github.com/hynek/structlog/issues/110) +- `structlog.stdlib.BoundLogger.exception()` now uses the `exc_info` argument if it has been passed instead of setting it unconditionally to `True`. [#149](https://github.com/hynek/structlog/pull/149) +- Default configuration now uses plain `dict`s on Python 3.6+ and PyPy since they are ordered by default. + + +### Fixed +- Do not encapsulate Twisted failures twice with newer versions of Twisted. + [#144](https://github.com/hynek/structlog/issues/144) + + +## [17.2.0](https://github.com/hynek/structlog/compare/17.1.0...17.2.0) - 2017-05-15 + +### Added + +- `structlog.stdlib.ProcessorFormatter` now accepts *keep_exc_info* and *keep_stack_info* arguments to control what to do with this information on log records. + Most likely you want them both to be `False` therefore it's the default. + [#109](https://github.com/hynek/structlog/issues/109) + + +### Fixed +- `structlog.stdlib.add_logger_name()` now works in `structlog.stdlib.ProcessorFormatter`'s `foreign_pre_chain`. + [#112](https://github.com/hynek/structlog/issues/112) +- Clear log record args in `structlog.stdlib.ProcessorFormatter` after rendering. + This fix is for you if you tried to use it and got `TypeError: not all arguments converted during string formatting` exceptions. + [#116](https://github.com/hynek/structlog/issues/116), + [#117](https://github.com/hynek/structlog/issues/117) + + +## [17.1.0](https://github.com/hynek/structlog/compare/16.1.0...17.1.0) - 2017-04-24 + +The main features of this release are massive improvements in standard library's `logging` integration. +Have a look at the updated [standard library chapter](https://www.structlog.org/en/stable/standard-library.html) on how to use them! +Special thanks go to [Fabian Büchler](https://github.com/fabianbuechler), [Gilbert Gilb's](https://github.com/gilbsgilbs), [Iva Kaneva](https://github.com/if-fi), [insolite](https://github.com/insolite), and [sky-code](https://github.com/sky-code), that made them possible. + + +### Added + +- Added `structlog.stdlib.render_to_log_kwargs()`. + This allows you to use `logging`-based formatters to take care of rendering your entries. + [#98](https://github.com/hynek/structlog/issues/98) +- Added `structlog.stdlib.ProcessorFormatter` which does the opposite: This allows you to run *structlog* processors on arbitrary `logging.LogRecords`. + [#79](https://github.com/hynek/structlog/issues/79), + [#105](https://github.com/hynek/structlog/issues/105) +- Added *repr_native_str* to `structlog.processors.KeyValueRenderer` and `structlog.dev.ConsoleRenderer`. + This allows for human-readable non-ASCII output on Python 2 (`repr()` on Python 2 behaves like `ascii()` on Python 3 in that regard). + As per compatibility policy, it's on (original behavior) in `KeyValueRenderer` and off (human-friendly behavior) in `ConsoleRenderer`. + [#94](https://github.com/hynek/structlog/issues/94) +- Added *colors* argument to `structlog.dev.ConsoleRenderer` and made it the default renderer. + [#78](https://github.com/hynek/structlog/pull/78) + + +### Changed + +- The default renderer now is `structlog.dev.ConsoleRenderer` if you don't configure *structlog*. + Colors are used if available and human-friendly timestamps are prepended. + This is in line with our backwards-compatibility policy that explicitly excludes default settings. +- UNIX epoch timestamps from `structlog.processors.TimeStamper` are more precise now. +- Positional arguments are now removed even if they are empty. + [#82](https://github.com/hynek/structlog/pull/82) + + +## Fixed + +- Fixed bug with Python 3 and `structlog.stdlib.BoundLogger.log()`. + Error log level was not reproducible and was logged as exception one time out of two. + [#92](https://github.com/hynek/structlog/pull/92) + + +## [16.1.0](https://github.com/hynek/structlog/compare/16.0.0...16.1.0) - 2016-05-24 + +### Removed + +- Python 3.3 and 2.6 aren't supported anymore. + They may work by chance but any effort to keep them working has ceased. + + The last Python 2.6 release was on October 29, 2013 and isn't supported by the CPython core team anymore. + Major Python packages like Django and Twisted dropped Python 2.6 a while ago already. + + Python 3.3 never had a significant user base and wasn't part of any distribution's LTS release. + + +### Added + +- Added a `drop_missing` argument to `KeyValueRenderer`. + If `key_order` is used and a key is missing a value, it's not rendered at all instead of being rendered as `None`. + [#67](https://github.com/hynek/structlog/pull/67) + + +### Fixed + +- Exceptions without a `__traceback__` are now also rendered on Python 3. +- Don't cache loggers in lazy proxies returned from `get_logger()`. + This lead to in-place mutation of them if used before configuration which in turn lead to the problem that configuration was applied only partially to them later. + [#72](https://github.com/hynek/structlog/pull/72) + + +## [16.0.0](https://github.com/hynek/structlog/compare/15.3.0...16.0.0) - 2016-01-28 + +### Added + +- Added `structlog.dev.ConsoleRenderer` that renders the event dictionary aligned and with colors. +- Added `structlog.processors.UnicodeDecoder` that will decode all byte string values in an event dictionary to Unicode. +- Added `serializer` parameter to `structlog.processors.JSONRenderer` which allows for using different (possibly faster) JSON encoders than the standard library. + + +### Changed + +- `structlog.processors.ExceptionPrettyPrinter` and `structlog.processors.format_exc_info` now support passing of Exceptions on Python 3. +- [*six*](https://six.readthedocs.io/) is now used for compatibility. + + +### Fixed + +- The context is now cleaned up when exiting `structlog.threadlocal.tmp_bind` in case of exceptions. + [#64](https://github.com/hynek/structlog/issues/64) +- Be more more lenient about missing `__name__`s. + [#62](https://github.com/hynek/structlog/pull/62) + + +## [15.3.0](https://github.com/hynek/structlog/compare/15.2.0...15.3.0) - 2015-09-25 + +### Added + +- Officially support Python 3.5. +- Added `structlog.ReturnLogger.failure` and `structlog.PrintLogger.failure` as preparation for the new Twisted logging system. + + +### Fixed + +- Tolerate frames without a `__name__`, better. + [#58](https://github.com/hynek/structlog/pull/58) + + +## [15.2.0](https://github.com/hynek/structlog/compare/15.1.0...15.2.0) - 2015-06-10 + +### Added + +- Added option to specify target key in `structlog.processors.TimeStamper` processor. + [#51](https://github.com/hynek/structlog/pull/51) + + +### Changed + +- Allow empty lists of processors. + This is a valid use case since [#26](https://github.com/hynek/structlog/issues/26) has been merged. + Before, supplying an empty list resulted in the defaults being used. +- Better support of `logging.Logger.exception` within *structlog*. + [#52](https://github.com/hynek/structlog/pull/52) + + +### Fixed + +- Prevent Twisted's `log.err` from quoting strings rendered by `structlog.twisted.JSONRenderer`. + + +## [15.1.0](https://github.com/hynek/structlog/compare/15.0.0...15.1.0) - 2015-02-24 + +### Fixed + +- Tolerate frames without a `__name__` when guessing callsite names. + + +## [15.0.0](https://github.com/hynek/structlog/compare/0.4.2...15.0.0) - 2015-01-23 + +### Added + +- Added `structlog.stdlib.add_log_level` and `structlog.stdlib.add_logger_name` processors. + [#44](https://github.com/hynek/structlog/pull/44) +- Added `structlog.stdlib.BoundLogger.log`. + [#42](https://github.com/hynek/structlog/pull/42) +- Added `structlog.stdlib.BoundLogger.exception`. + [#22](https://github.com/hynek/structlog/pull/22) + + +### Changed + +- Pass positional arguments to stdlib wrapped loggers that use string formatting. + [#19](https://github.com/hynek/structlog/pull/19) +- *structlog* is now dually licensed under the [Apache License, Version 2](https://choosealicense.com/licenses/apache/) and the [MIT](https://choosealicense.com/licenses/mit/) license. + Therefore it is now legal to use *structlog* with [GPLv2](https://choosealicense.com/licenses/gpl-2.0/)-licensed projects. + [#28](https://github.com/hynek/structlog/pull/28) + + +## [0.4.2](https://github.com/hynek/structlog/compare/0.4.1...0.4.2) - 2014-07-26 + +### Removed + +- Drop support for Python 3.2. + There is no justification to add complexity for a Python version that nobody uses. + If you are one of the [0.350%](https://alexgaynor.net/2014/jan/03/pypi-download-statistics/) that use Python 3.2, please stick to the 0.4 branch; critical bugs will still be fixed. + + +### Added + +- Officially support Python 3.4. +- Allow final processor to return a dictionary. + See the adapting chapter. + [#26](https://github.com/hynek/structlog/issues/26) +- Test Twisted-related code on Python 3 (with some caveats). + + +### Fixed + +- Fixed a memory leak in greenlet code that emulates thread locals. + It shouldn't matter in practice unless you use multiple wrapped dicts within one program that is rather unlikely. + [#8](https://github.com/hynek/structlog/pull/8) +- `structlog.PrintLogger` now is thread-safe. +- `from structlog import *` works now (but you still shouldn't use it). + + +## [0.4.1](https://github.com/hynek/structlog/compare/0.4.0...0.4.1) - 2013-12-19 + +### Changed + +- Don't cache proxied methods in `structlog.threadlocal._ThreadLocalDictWrapper`. This doesn't affect regular users. + + +### Fixed + +- Various doc fixes. + + +## [0.4.0](https://github.com/hynek/structlog/compare/0.3.2...0.4.0) - 2013-11-10 + +### Added + +- Added `structlog.processors.StackInfoRenderer` for adding stack information to log entries without involving exceptions. + Also added it to default processor chain. + [#6](https://github.com/hynek/structlog/pull/6) +- Allow optional positional arguments for `structlog.get_logger` that are passed to logger factories. + The standard library factory uses this for explicit logger naming. + [#12](https://github.com/hynek/structlog/pull/12) +- Add `structlog.processors.ExceptionPrettyPrinter` for development and testing when multiline log entries aren't just acceptable but even helpful. +- Allow the standard library name guesser to ignore certain frame names. + This is useful together with frameworks. +- Add meta data (for example, function names, line numbers) extraction for wrapped stdlib loggers. [#5](https://github.com/hynek/structlog/pull/5) + + +## [0.3.2](https://github.com/hynek/structlog/compare/0.3.1...0.3.2) - 2013-09-27 + +### Fixed + +- Fix stdlib's name guessing. + + +## [0.3.1](https://github.com/hynek/structlog/compare/0.3.0...0.3.1) - 2013-09-26 + +### Fixed + +- Added forgotten `structlog.processors.TimeStamper` to API documentation. + + +## [0.3.0](https://github.com/hynek/structlog/compare/0.2.0...0.3.0) - 2013-09-23 + +### Changes: + +- Greatly enhanced and polished the documentation and added a new theme based on Write The Docs, requests, and Flask. +- Add Python Standard Library-specific BoundLogger that has an explicit API instead of intercepting unknown method calls. + See `structlog.stdlib.BoundLogger`. +- `structlog.ReturnLogger` now allows arbitrary positional and keyword arguments. +- Add Twisted-specific BoundLogger that has an explicit API instead of intercepting unknown method calls. + See `structlog.twisted.BoundLogger`. +- Allow logger proxies that are returned by `structlog.get_logger` and `structlog.wrap_logger` to cache the BoundLogger they assemble according to configuration on first use. + See the chapter on performance and the `cache_logger_on_first_use` argument of `structlog.configure` and `structlog.wrap_logger`. +- Extract a common base class for loggers that does nothing except keeping the context state. + This makes writing custom loggers much easier and more straight-forward. See `structlog.BoundLoggerBase`. + + +## [0.2.0](https://github.com/hynek/structlog/compare/0.1.0...0.2.0) - 2013-09-17 + +### Added + +- Add `key_order` option to `structlog.processors.KeyValueRenderer` for more predictable log entries with any `dict` class. +- Enhance Twisted support by offering JSONification of non-structlog log entries. +- Allow for custom serialization in `structlog.twisted.JSONRenderer` without abusing `__repr__`. + + +### Changed + +- Promote to stable, thus henceforth a strict backwards-compatibility policy is put into effect. +- `structlog.PrintLogger` now uses proper I/O routines and is thus viable not only for examples but also for production. + + +## [0.1.0](https://github.com/hynek/structlog/tree/0.1.0) - 2013-09-16 + +Initial release. diff --git a/src/structlog/stdlib.py b/src/structlog/stdlib.py new file mode 100644 index 0000000..2906598 --- /dev/null +++ b/src/structlog/stdlib.py @@ -0,0 +1,1258 @@ +# This file is dual licensed under the terms of the Apache License, Version +# 2.0, and the MIT License. See the LICENSE file in the root of this +# repository for complete details. + +""" +Processors and helpers specific to the :mod:`logging` module from the `Python +standard library `_. + +See also :doc:`structlog's standard library support `. +""" + +from __future__ import annotations + +import asyncio +import contextvars +import functools +import logging +import sys +import threading +import warnings + +from collections.abc import Callable, Collection, Iterable, Sequence +from functools import partial +from typing import Any, cast + + +if sys.version_info >= (3, 11): + from typing import Self +else: + from typing_extensions import Self + + +from . import _config +from ._base import BoundLoggerBase +from ._frames import _find_first_app_frame_and_name, _format_stack +from ._log_levels import LEVEL_TO_NAME, NAME_TO_LEVEL, add_log_level +from .contextvars import ( + _ASYNC_CALLING_STACK, + _ASYNC_CALLING_THREAD, + merge_contextvars, +) +from .exceptions import DropEvent +from .processors import StackInfoRenderer +from .typing import ( + Context, + EventDict, + ExcInfo, + Processor, + ProcessorReturnValue, + WrappedLogger, +) + + +__all__ = [ + "BoundLogger", + "ExtraAdder", + "LoggerFactory", + "PositionalArgumentsFormatter", + "ProcessorFormatter", + "add_log_level", + "add_log_level_number", + "add_logger_name", + "filter_by_level", + "get_logger", + "recreate_defaults", + "render_to_log_args_and_kwargs", + "render_to_log_kwargs", +] + + +def recreate_defaults(*, log_level: int | None = logging.NOTSET) -> None: + """ + Recreate defaults on top of standard library's logging. + + The output looks the same, but goes through `logging`. + + As with vanilla defaults, the backwards-compatibility guarantees don't + apply to the settings applied here. + + Args: + log_level: + If `None`, don't configure standard library logging **at all**. + + Otherwise configure it to log to `sys.stdout` at *log_level* + (``logging.NOTSET`` being the default). + + If you need more control over `logging`, pass `None` here and + configure it yourself. + + .. versionadded:: 22.1.0 + .. versionchanged:: 23.3.0 Added `add_logger_name`. + .. versionchanged:: 25.1.0 Added `PositionalArgumentsFormatter`. + """ + if log_level is not None: + kw = {"force": True} + + logging.basicConfig( + format="%(message)s", + stream=sys.stdout, + level=log_level, + **kw, # type: ignore[call-overload] + ) + + _config.reset_defaults() + _config.configure( + processors=[ + PositionalArgumentsFormatter(), # handled by native loggers + merge_contextvars, + add_log_level, + add_logger_name, + StackInfoRenderer(), + _config._BUILTIN_DEFAULT_PROCESSORS[-2], # TimeStamper + _config._BUILTIN_DEFAULT_PROCESSORS[-1], # ConsoleRenderer + ], + wrapper_class=BoundLogger, + logger_factory=LoggerFactory(), + ) + + +_SENTINEL = object() + + +class _FixedFindCallerLogger(logging.Logger): + """ + Change the behavior of `logging.Logger.findCaller` to cope with + *structlog*'s extra frames. + """ + + def findCaller( + self, stack_info: bool = False, stacklevel: int = 1 + ) -> tuple[str, int, str, str | None]: + """ + Finds the first caller frame outside of structlog so that the caller + info is populated for wrapping stdlib. + + This logger gets set as the default one when using LoggerFactory. + """ + sinfo: str | None + # stdlib logging passes stacklevel=1 from log methods like .warning(), + # but we've already skipped those frames by ignoring "logging", so we + # need to adjust stacklevel down by 1. We need to manually drop + # logging frames, because there's cases where we call logging methods + # from within structlog and the stacklevel offsets don't work anymore. + adjusted_stacklevel = max(0, stacklevel - 1) if stacklevel else None + f, _name = _find_first_app_frame_and_name( + ["logging"], stacklevel=adjusted_stacklevel + ) + sinfo = _format_stack(f) if stack_info else None + + return f.f_code.co_filename, f.f_lineno, f.f_code.co_name, sinfo + + +class BoundLogger(BoundLoggerBase): + """ + Python Standard Library version of `structlog.BoundLogger`. + + Works exactly like the generic one except that it takes advantage of + knowing the logging methods in advance. + + Use it like:: + + structlog.configure( + wrapper_class=structlog.stdlib.BoundLogger, + ) + + It also contains a bunch of properties that pass-through to the wrapped + `logging.Logger` which should make it work as a drop-in replacement. + + .. versionadded:: 23.1.0 + Async variants `alog()`, `adebug()`, `ainfo()`, and so forth. + + .. versionchanged:: 24.2.0 + Callsite parameters are now also collected by + `structlog.processors.CallsiteParameterAdder` for async log methods. + """ + + _logger: logging.Logger + + def bind(self, **new_values: Any) -> Self: + """ + Return a new logger with *new_values* added to the existing ones. + """ + return super().bind(**new_values) + + def unbind(self, *keys: str) -> Self: + """ + Return a new logger with *keys* removed from the context. + + Raises: + KeyError: If the key is not part of the context. + """ + return super().unbind(*keys) + + def try_unbind(self, *keys: str) -> Self: + """ + Like :meth:`unbind`, but best effort: missing keys are ignored. + + .. versionadded:: 18.2.0 + """ + return super().try_unbind(*keys) + + def new(self, **new_values: Any) -> Self: + """ + Clear context and binds *initial_values* using `bind`. + + Only necessary with dict implementations that keep global state like + those wrapped by `structlog.threadlocal.wrap_dict` when threads + are reused. + """ + return super().new(**new_values) + + def debug(self, event: str | None = None, *args: Any, **kw: Any) -> Any: + """ + Process event and call `logging.Logger.debug` with the result. + """ + return self._proxy_to_logger("debug", event, *args, **kw) + + def info(self, event: str | None = None, *args: Any, **kw: Any) -> Any: + """ + Process event and call `logging.Logger.info` with the result. + """ + return self._proxy_to_logger("info", event, *args, **kw) + + def warning(self, event: str | None = None, *args: Any, **kw: Any) -> Any: + """ + Process event and call `logging.Logger.warning` with the result. + """ + return self._proxy_to_logger("warning", event, *args, **kw) + + warn = warning + + def error(self, event: str | None = None, *args: Any, **kw: Any) -> Any: + """ + Process event and call `logging.Logger.error` with the result. + """ + return self._proxy_to_logger("error", event, *args, **kw) + + def critical(self, event: str | None = None, *args: Any, **kw: Any) -> Any: + """ + Process event and call `logging.Logger.critical` with the result. + """ + return self._proxy_to_logger("critical", event, *args, **kw) + + def fatal(self, event: str | None = None, *args: Any, **kw: Any) -> Any: + """ + Process event and call `logging.Logger.critical` with the result. + """ + return self._proxy_to_logger("critical", event, *args, **kw) + + def exception( + self, event: str | None = None, *args: Any, **kw: Any + ) -> Any: + """ + Process event and call `logging.Logger.exception` with the result, + after setting ``exc_info`` to `True` if it's not already set. + """ + kw.setdefault("exc_info", True) + return self._proxy_to_logger("exception", event, *args, **kw) + + def log( + self, level: int, event: str | None = None, *args: Any, **kw: Any + ) -> Any: + """ + Process *event* and call the appropriate logging method depending on + *level*. + """ + return self._proxy_to_logger(LEVEL_TO_NAME[level], event, *args, **kw) + + def _proxy_to_logger( + self, + method_name: str, + event: str | None = None, + *event_args: str, + **event_kw: Any, + ) -> Any: + """ + Propagate a method call to the wrapped logger. + + This is the same as the superclass implementation, except that + it also preserves positional arguments in the ``event_dict`` so + that the stdlib's support for format strings can be used. + """ + if event_args: + event_kw["positional_args"] = event_args + + return super()._proxy_to_logger(method_name, event=event, **event_kw) + + # Pass-through attributes and methods to mimic the stdlib's logger + # interface. + + @property + def name(self) -> str: + """ + Returns :attr:`logging.Logger.name` + """ + return self._logger.name + + @property + def level(self) -> int: + """ + Returns :attr:`logging.Logger.level` + """ + return self._logger.level + + @property + def parent(self) -> Any: + """ + Returns :attr:`logging.Logger.parent` + """ + return self._logger.parent + + @property + def propagate(self) -> bool: + """ + Returns :attr:`logging.Logger.propagate` + """ + return self._logger.propagate + + @property + def handlers(self) -> Any: + """ + Returns :attr:`logging.Logger.handlers` + """ + return self._logger.handlers + + @property + def disabled(self) -> int: + """ + Returns :attr:`logging.Logger.disabled` + """ + return self._logger.disabled + + def setLevel(self, level: int) -> None: + """ + Calls :meth:`logging.Logger.setLevel` with unmodified arguments. + """ + self._logger.setLevel(level) + + def findCaller( + self, stack_info: bool = False, stacklevel: int = 1 + ) -> tuple[str, int, str, str | None]: + """ + Calls :meth:`logging.Logger.findCaller` with unmodified arguments. + """ + # No need for stacklevel-adjustments since we're within structlog and + # our frames are ignored unconditionally. + return self._logger.findCaller( + stack_info=stack_info, stacklevel=stacklevel + ) + + def makeRecord( + self, + name: str, + level: int, + fn: str, + lno: int, + msg: str, + args: tuple[Any, ...], + exc_info: ExcInfo, + func: str | None = None, + extra: Any = None, + ) -> logging.LogRecord: + """ + Calls :meth:`logging.Logger.makeRecord` with unmodified arguments. + """ + return self._logger.makeRecord( + name, level, fn, lno, msg, args, exc_info, func=func, extra=extra + ) + + def handle(self, record: logging.LogRecord) -> None: + """ + Calls :meth:`logging.Logger.handle` with unmodified arguments. + """ + self._logger.handle(record) + + def addHandler(self, hdlr: logging.Handler) -> None: + """ + Calls :meth:`logging.Logger.addHandler` with unmodified arguments. + """ + self._logger.addHandler(hdlr) + + def removeHandler(self, hdlr: logging.Handler) -> None: + """ + Calls :meth:`logging.Logger.removeHandler` with unmodified arguments. + """ + self._logger.removeHandler(hdlr) + + def hasHandlers(self) -> bool: + """ + Calls :meth:`logging.Logger.hasHandlers` with unmodified arguments. + + Exists only in Python 3. + """ + return self._logger.hasHandlers() + + def callHandlers(self, record: logging.LogRecord) -> None: + """ + Calls :meth:`logging.Logger.callHandlers` with unmodified arguments. + """ + self._logger.callHandlers(record) + + def getEffectiveLevel(self) -> int: + """ + Calls :meth:`logging.Logger.getEffectiveLevel` with unmodified + arguments. + """ + return self._logger.getEffectiveLevel() + + def isEnabledFor(self, level: int) -> bool: + """ + Calls :meth:`logging.Logger.isEnabledFor` with unmodified arguments. + """ + return self._logger.isEnabledFor(level) + + def is_enabled_for(self, level: int) -> bool: + """ + A snake_case alias of `isEnabledFor` for compatibility with + `structlog.typing.FilteringBoundLogger`. + + .. note:: + + This method is more complex than the native `is_enabled_for` since + it supports standard library-only features like + :attr:`logging.Logger.disabled` while the native one only compares + log levels. + + .. versionadded:: 26.1.0 + """ + return self._logger.isEnabledFor(level) + + def get_effective_level(self) -> int: + """ + A snake_case alias of `getEffectiveLevel` for compatibility with + `structlog.typing.FilteringBoundLogger`. + + .. versionadded:: 26.1.0 + """ + return self._logger.getEffectiveLevel() + + def getChild(self, suffix: str) -> logging.Logger: + """ + Calls :meth:`logging.Logger.getChild` with unmodified arguments. + """ + return self._logger.getChild(suffix) + + # Non-Standard Async + async def _dispatch_to_sync( + self, + meth: Callable[..., Any], + event: str, + args: tuple[Any, ...], + kw: dict[str, Any], + ) -> None: + """ + Merge contextvars and log using the sync logger in a thread pool. + """ + # Capture thread-specific info before handing off to the executor. + thread_token = _ASYNC_CALLING_THREAD.set( + (threading.get_ident(), threading.current_thread().name) + ) + scs_token = _ASYNC_CALLING_STACK.set(sys._getframe().f_back.f_back) # type: ignore[union-attr, arg-type, unused-ignore] + ctx = contextvars.copy_context() + + try: + await asyncio.get_running_loop().run_in_executor( + None, + lambda: ctx.run(lambda: meth(event, *args, **kw)), + ) + finally: + _ASYNC_CALLING_STACK.reset(scs_token) + _ASYNC_CALLING_THREAD.reset(thread_token) + + async def adebug(self, event: str, *args: Any, **kw: Any) -> None: + """ + Log using `debug()`, but asynchronously in a separate thread. + + .. versionadded:: 23.1.0 + """ + await self._dispatch_to_sync(self.debug, event, args, kw) + + async def ainfo(self, event: str, *args: Any, **kw: Any) -> None: + """ + Log using `info()`, but asynchronously in a separate thread. + + .. versionadded:: 23.1.0 + """ + await self._dispatch_to_sync(self.info, event, args, kw) + + async def awarning(self, event: str, *args: Any, **kw: Any) -> None: + """ + Log using `warning()`, but asynchronously in a separate thread. + + .. versionadded:: 23.1.0 + """ + await self._dispatch_to_sync(self.warning, event, args, kw) + + async def aerror(self, event: str, *args: Any, **kw: Any) -> None: + """ + Log using `error()`, but asynchronously in a separate thread. + + .. versionadded:: 23.1.0 + """ + await self._dispatch_to_sync(self.error, event, args, kw) + + async def acritical(self, event: str, *args: Any, **kw: Any) -> None: + """ + Log using `critical()`, but asynchronously in a separate thread. + + .. versionadded:: 23.1.0 + """ + await self._dispatch_to_sync(self.critical, event, args, kw) + + async def afatal(self, event: str, *args: Any, **kw: Any) -> None: + """ + Log using `critical()`, but asynchronously in a separate thread. + + .. versionadded:: 23.1.0 + """ + await self._dispatch_to_sync(self.critical, event, args, kw) + + async def aexception(self, event: str, *args: Any, **kw: Any) -> None: + """ + Log using `exception()`, but asynchronously in a separate thread. + + .. versionadded:: 23.1.0 + """ + # To make `log.exception("foo") work, we have to check if the user + # passed an explicit exc_info and if not, supply our own. + if kw.get("exc_info", True) is True and kw.get("exception") is None: + kw["exc_info"] = sys.exc_info() + + await self._dispatch_to_sync(self.exception, event, args, kw) + + async def alog( + self, level: Any, event: str, *args: Any, **kw: Any + ) -> None: + """ + Log using `log()`, but asynchronously in a separate thread. + + .. versionadded:: 23.1.0 + """ + await self._dispatch_to_sync(partial(self.log, level), event, args, kw) + + +def get_logger(*args: Any, **initial_values: Any) -> BoundLogger: + """ + Only calls `structlog.get_logger`, but has the correct type hints. + + .. warning:: + + Does **not** check whether -- or ensure that -- you've configured + *structlog* for standard library :mod:`logging`! + + See :doc:`standard-library` for details. + + .. versionadded:: 20.2.0 + """ + return _config.get_logger(*args, **initial_values) + + +class AsyncBoundLogger: + """ + Wraps a `BoundLogger` & exposes its logging methods as ``async`` versions. + + This approach has turned out to be a mistake and the class has been + deprecated in 23.1.0. Use the regular `BoundLogger` with its a-prefixed + methods instead. + + .. versionadded:: 20.2.0 + .. versionchanged:: 20.2.0 fix _dispatch_to_sync contextvars usage + .. deprecated:: 23.1.0 + Use the regular `BoundLogger` with its a-prefixed methods instead. + .. versionchanged:: 23.3.0 + Callsite parameters are now also collected for async log methods. + """ + + __slots__ = ("_loop", "sync_bl") + + #: The wrapped synchronous logger. It is useful to be able to log + #: synchronously occasionally. + sync_bl: BoundLogger + + _executor = None + _bound_logger_factory = BoundLogger + + def __init__( + self, + logger: logging.Logger, + processors: Iterable[Processor], + context: Context, + *, + # Only as an optimization for binding! + _sync_bl: Any = None, # *vroom vroom* over purity. + _loop: Any = None, + ): + if _sync_bl: + self.sync_bl = _sync_bl + self._loop = _loop + + return + + self.sync_bl = self._bound_logger_factory( + logger=logger, processors=processors, context=context + ) + self._loop = asyncio.get_running_loop() + + # Instances would've been correctly recognized as such, however the class + # not and we need the class in `structlog.configure()`. + @property + def _context(self) -> Context: + return self.sync_bl._context + + def bind(self, **new_values: Any) -> Self: + return self.__class__( + # logger, processors and context are within sync_bl. These + # arguments are ignored if _sync_bl is passed. *vroom vroom* over + # purity. + logger=None, # type: ignore[arg-type] + processors=(), + context={}, + _sync_bl=self.sync_bl.bind(**new_values), + _loop=self._loop, + ) + + def new(self, **new_values: Any) -> Self: + return self.__class__( + # c.f. comment in bind + logger=None, # type: ignore[arg-type] + processors=(), + context={}, + _sync_bl=self.sync_bl.new(**new_values), + _loop=self._loop, + ) + + def unbind(self, *keys: str) -> Self: + return self.__class__( + # c.f. comment in bind + logger=None, # type: ignore[arg-type] + processors=(), + context={}, + _sync_bl=self.sync_bl.unbind(*keys), + _loop=self._loop, + ) + + def try_unbind(self, *keys: str) -> Self: + return self.__class__( + # c.f. comment in bind + logger=None, # type: ignore[arg-type] + processors=(), + context={}, + _sync_bl=self.sync_bl.try_unbind(*keys), + _loop=self._loop, + ) + + async def _dispatch_to_sync( + self, + meth: Callable[..., Any], + event: str, + args: tuple[Any, ...], + kw: dict[str, Any], + ) -> None: + """ + Merge contextvars and log using the sync logger in a thread pool. + """ + # Capture thread-specific info before handing off to the executor. + thread_token = _ASYNC_CALLING_THREAD.set( + (threading.get_ident(), threading.current_thread().name) + ) + scs_token = _ASYNC_CALLING_STACK.set(sys._getframe().f_back.f_back) # type: ignore[union-attr, arg-type, unused-ignore] + ctx = contextvars.copy_context() + + try: + await asyncio.get_running_loop().run_in_executor( + self._executor, + lambda: ctx.run(lambda: meth(event, *args, **kw)), + ) + finally: + _ASYNC_CALLING_STACK.reset(scs_token) + _ASYNC_CALLING_THREAD.reset(thread_token) + + async def debug(self, event: str, *args: Any, **kw: Any) -> None: + await self._dispatch_to_sync(self.sync_bl.debug, event, args, kw) + + async def info(self, event: str, *args: Any, **kw: Any) -> None: + await self._dispatch_to_sync(self.sync_bl.info, event, args, kw) + + async def warning(self, event: str, *args: Any, **kw: Any) -> None: + await self._dispatch_to_sync(self.sync_bl.warning, event, args, kw) + + async def warn(self, event: str, *args: Any, **kw: Any) -> None: + await self._dispatch_to_sync(self.sync_bl.warning, event, args, kw) + + async def error(self, event: str, *args: Any, **kw: Any) -> None: + await self._dispatch_to_sync(self.sync_bl.error, event, args, kw) + + async def critical(self, event: str, *args: Any, **kw: Any) -> None: + await self._dispatch_to_sync(self.sync_bl.critical, event, args, kw) + + async def fatal(self, event: str, *args: Any, **kw: Any) -> None: + await self._dispatch_to_sync(self.sync_bl.critical, event, args, kw) + + async def exception(self, event: str, *args: Any, **kw: Any) -> None: + # To make `log.exception("foo") work, we have to check if the user + # passed an explicit exc_info and if not, supply our own. + ei = kw.pop("exc_info", None) + if ei is None and kw.get("exception") is None: + ei = sys.exc_info() + + kw["exc_info"] = ei + + await self._dispatch_to_sync(self.sync_bl.exception, event, args, kw) + + async def log(self, level: Any, event: str, *args: Any, **kw: Any) -> None: + await self._dispatch_to_sync( + partial(self.sync_bl.log, level), event, args, kw + ) + + +class LoggerFactory: + """ + Build a standard library logger when an *instance* is called. + + Sets a custom logger using :func:`logging.setLoggerClass` so variables in + log format are expanded properly. + + >>> from structlog import configure + >>> from structlog.stdlib import LoggerFactory + >>> configure(logger_factory=LoggerFactory()) + + Args: + ignore_frame_names: + When guessing the name of a logger, skip frames whose names *start* + with one of these. For example, in pyramid applications you'll + want to set it to ``["venusian", "pyramid.config"]``. This argument + is called *additional_ignores* in other APIs throughout + *structlog*. + """ + + def __init__(self, ignore_frame_names: list[str] | None = None): + self._ignore = ignore_frame_names + logging.setLoggerClass(_FixedFindCallerLogger) + + def __call__(self, *args: Any) -> logging.Logger: + """ + Deduce the caller's module name and create a stdlib logger. + + If an optional argument is passed, it will be used as the logger name + instead of guesswork. This optional argument would be passed from the + :func:`structlog.get_logger` call. For example + ``structlog.get_logger("foo")`` would cause this method to be called + with ``"foo"`` as its first positional argument. + + .. versionchanged:: 0.4.0 + Added support for optional positional arguments. Using the first + one for naming the constructed logger. + """ + if args: + return logging.getLogger(args[0]) + + # We skip all frames that originate from within structlog or one of the + # configured names. + _, name = _find_first_app_frame_and_name(self._ignore) + + return logging.getLogger(name) + + +class PositionalArgumentsFormatter: + """ + Apply stdlib-like string formatting to the ``event`` key. + + If the ``positional_args`` key in the event dict is set, it must + contain a tuple that is used for formatting (using the ``%s`` string + formatting operator) of the value from the ``event`` key. This works + in the same way as the stdlib handles arguments to the various log + methods: if the tuple contains only a single `dict` argument it is + used for keyword placeholders in the ``event`` string, otherwise it + will be used for positional placeholders. + + ``positional_args`` is populated by `structlog.stdlib.BoundLogger` or + can be set manually. + + The *remove_positional_args* flag can be set to `False` to keep the + ``positional_args`` key in the event dict; by default it will be + removed from the event dict after formatting a message. + """ + + remove_positional_args: bool + + def __init__(self, remove_positional_args: bool = True) -> None: + self.remove_positional_args = remove_positional_args + + def __call__( + self, _: WrappedLogger, __: str, event_dict: EventDict + ) -> EventDict: + args = event_dict.get("positional_args") + + # Mimic the formatting behaviour of the stdlib's logging module, which + # accepts both positional arguments and a single dict argument. The + # "single dict" check is the same one as the stdlib's logging module + # performs in LogRecord.__init__(). + if args: + if len(args) == 1 and isinstance(args[0], dict) and args[0]: + args = args[0] + + event_dict["event"] %= args + + if self.remove_positional_args and args is not None: + del event_dict["positional_args"] + + return event_dict + + +def filter_by_level( + logger: logging.Logger, method_name: str, event_dict: EventDict +) -> EventDict: + """ + Check whether logging is configured to accept messages from this log level. + + Should be the first processor if stdlib's filtering by level is used so + possibly expensive processors like exception formatters are avoided in the + first place. + + >>> import logging + >>> from structlog.stdlib import filter_by_level + >>> logging.basicConfig(level=logging.WARN) + >>> logger = logging.getLogger() + >>> filter_by_level(logger, 'warn', {}) + {} + >>> filter_by_level(logger, 'debug', {}) + Traceback (most recent call last): + ... + DropEvent + """ + if ( + # We can't use logger.isEnabledFor() because it's always disabled when + # a log entry is in flight on Python 3.14 and later, + not logger.disabled + and NAME_TO_LEVEL[method_name] >= logger.getEffectiveLevel() + ): + return event_dict + + raise DropEvent + + +def add_log_level_number( + logger: logging.Logger, method_name: str, event_dict: EventDict +) -> EventDict: + """ + Add the log level number to the event dict. + + Log level numbers map to the log level names. The Python stdlib uses them + for filtering logic. This adds the same numbers so users can leverage + similar filtering. Compare:: + + level in ("warning", "error", "critical") + level_number >= 30 + + The mapping of names to numbers is in + ``structlog.stdlib._log_levels._NAME_TO_LEVEL``. + + .. versionadded:: 18.2.0 + """ + event_dict["level_number"] = NAME_TO_LEVEL[method_name] + + return event_dict + + +def add_logger_name( + logger: logging.Logger, method_name: str, event_dict: EventDict +) -> EventDict: + """ + Add the logger name to the event dict. + """ + record = event_dict.get("_record") + if record is None: + event_dict["logger"] = logger.name + else: + event_dict["logger"] = record.name + return event_dict + + +_LOG_RECORD_KEYS = logging.LogRecord( + "name", 0, "pathname", 0, "msg", (), None +).__dict__.keys() + + +class ExtraAdder: + """ + Add extra attributes of `logging.LogRecord` objects to the event + dictionary. + + This processor can be used for adding data passed in the ``extra`` + parameter of the `logging` module's log methods to the event dictionary. + + Args: + allow: + An optional collection of attributes that, if present in + `logging.LogRecord` objects, will be copied to event dictionaries. + + If ``allow`` is None all attributes of `logging.LogRecord` objects + that do not exist on a standard `logging.LogRecord` object will be + copied to event dictionaries. + + .. versionadded:: 21.5.0 + """ + + __slots__ = ("_copier",) + + def __init__(self, allow: Collection[str] | None = None) -> None: + self._copier: Callable[[EventDict, logging.LogRecord], None] + if allow is not None: + # The contents of allow is copied to a new list so that changes to + # the list passed into the constructor does not change the + # behaviour of this processor. + self._copier = functools.partial(self._copy_allowed, [*allow]) + else: + self._copier = self._copy_all + + def __call__( + self, logger: logging.Logger, name: str, event_dict: EventDict + ) -> EventDict: + record: logging.LogRecord | None = event_dict.get("_record") + if record is not None: + self._copier(event_dict, record) + return event_dict + + @classmethod + def _copy_all( + cls, event_dict: EventDict, record: logging.LogRecord + ) -> None: + for key, value in record.__dict__.items(): + if key not in _LOG_RECORD_KEYS: + event_dict[key] = value + + @classmethod + def _copy_allowed( + cls, + allow: Collection[str], + event_dict: EventDict, + record: logging.LogRecord, + ) -> None: + for key in allow: + if key in record.__dict__: + event_dict[key] = record.__dict__[key] + + +LOG_KWARG_NAMES = ("exc_info", "stack_info", "stacklevel") + + +def render_to_log_args_and_kwargs( + _: logging.Logger, __: str, event_dict: EventDict +) -> tuple[tuple[Any, ...], dict[str, Any]]: + """ + Render ``event_dict`` into positional and keyword arguments for + `logging.Logger` logging methods. + See `logging.Logger.debug` method for keyword arguments reference. + + The ``event`` field is passed in the first positional argument, positional + arguments from ``positional_args`` field are passed in subsequent positional + arguments, keyword arguments are extracted from the *event_dict* and the + rest of the *event_dict* is added as ``extra``. + + This allows you to defer formatting to `logging`. + + .. versionadded:: 25.1.0 + """ + args = (event_dict.pop("event"), *event_dict.pop("positional_args", ())) + + kwargs = { + kwarg_name: event_dict.pop(kwarg_name) + for kwarg_name in LOG_KWARG_NAMES + if kwarg_name in event_dict + } + if event_dict: + kwargs["extra"] = event_dict + + return args, kwargs + + +def render_to_log_kwargs( + _: logging.Logger, __: str, event_dict: EventDict +) -> EventDict: + """ + Render ``event_dict`` into keyword arguments for `logging.Logger` logging + methods. + See `logging.Logger.debug` method for keyword arguments reference. + + The ``event`` field is translated into ``msg``, keyword arguments are + extracted from the *event_dict* and the rest of the *event_dict* is added as + ``extra``. + + This allows you to defer formatting to `logging`. + + .. versionadded:: 17.1.0 + .. versionchanged:: 22.1.0 + ``exc_info``, ``stack_info``, and ``stacklevel`` are passed as proper + kwargs and not put into ``extra``. + .. versionchanged:: 24.2.0 + ``stackLevel`` corrected to ``stacklevel``. + """ + return { + "msg": event_dict.pop("event"), + "extra": event_dict, + **{ + kw: event_dict.pop(kw) + for kw in LOG_KWARG_NAMES + if kw in event_dict + }, + } + + +class ProcessorFormatter(logging.Formatter): + r""" + Call *structlog* processors on `logging.LogRecord`\s. + + This is an implementation of a `logging.Formatter` that can be used to + format log entries from both *structlog* and `logging`. + + Its static method `wrap_for_formatter` must be the final processor in + *structlog*'s processor chain. + + Please refer to :ref:`processor-formatter` for examples. + + Args: + foreign_pre_chain: + If not `None`, it is used as a processor chain that is applied to + **non**-*structlog* log entries before the event dictionary is + passed to *processors*. (default: `None`) + + processors: + A chain of *structlog* processors that is used to process **all** + log entries. The last one must render to a `str` which then gets + passed on to `logging` for output. + + Compared to *structlog*'s regular processor chains, there's a few + differences: + + - The event dictionary contains two additional keys: + + #. ``_record``: a `logging.LogRecord` that either was created + using `logging` APIs, **or** is a wrapped *structlog* log + entry created by `wrap_for_formatter`. + + #. ``_from_structlog``: a `bool` that indicates whether or not + ``_record`` was created by a *structlog* logger. + + Since you most likely don't want ``_record`` and + ``_from_structlog`` in your log files, we've added the static + method `remove_processors_meta` to ``ProcessorFormatter`` that + you can add just before your renderer. + + - Since this is a `logging` *formatter*, raising + `structlog.DropEvent` will crash your application. + + keep_exc_info: + ``exc_info`` on `logging.LogRecord`\ s is added to the + ``event_dict`` and removed afterwards. Set this to ``True`` to keep + it on the `logging.LogRecord`. (default: False) + + keep_stack_info: + Same as *keep_exc_info* except for ``stack_info``. (default: False) + + logger: + Logger which we want to push through the *structlog* processor + chain. This parameter is necessary for some of the processors like + `filter_by_level`. (default: None) + + pass_foreign_args: + If True, pass a foreign log record's ``args`` attribute to the + ``event_dict`` under ``positional_args`` key. (default: False) + + processor: + A single *structlog* processor used for rendering the event + dictionary before passing it off to `logging`. Must return a `str`. + The event dictionary does **not** contain ``_record`` and + ``_from_structlog``. + + This parameter exists for historic reasons. Please use *processors* + instead. + + use_get_message: + If True, use ``record.getMessage`` to get a fully rendered log + message, otherwise use ``str(record.msg)``. (default: True) + + Raises: + TypeError: If both or neither *processor* and *processors* are passed. + + .. versionadded:: 17.1.0 + .. versionadded:: 17.2.0 *keep_exc_info* and *keep_stack_info* + .. versionadded:: 19.2.0 *logger* + .. versionadded:: 19.2.0 *pass_foreign_args* + .. versionadded:: 21.3.0 *processors* + .. deprecated:: 21.3.0 + *processor* (singular) in favor of *processors* (plural). Removal is not + planned. + .. versionadded:: 23.3.0 *use_get_message* + """ + + processors: Sequence[Processor] + foreign_pre_chain: Sequence[Processor] | None + keep_exc_info: bool + keep_stack_info: bool + logger: logging.Logger | None + pass_foreign_args: bool + use_get_message: bool + + def __init__( + self, + processor: Processor | None = None, + processors: Sequence[Processor] | None = (), + foreign_pre_chain: Sequence[Processor] | None = None, + keep_exc_info: bool = False, + keep_stack_info: bool = False, + logger: logging.Logger | None = None, + pass_foreign_args: bool = False, + use_get_message: bool = True, + *args: Any, + **kwargs: Any, + ) -> None: + fmt = kwargs.pop("fmt", "%(message)s") + super().__init__(*args, fmt=fmt, **kwargs) # type: ignore[misc] + + if processor and processors: + msg = ( + "The `processor` and `processors` arguments are mutually" + " exclusive." + ) + raise TypeError(msg) + + if processor is not None: + self.processors = (self.remove_processors_meta, processor) + elif processors: + self.processors = processors + else: + msg = "Either `processor` or `processors` must be passed." + raise TypeError(msg) + + self.foreign_pre_chain = foreign_pre_chain + self.keep_exc_info = keep_exc_info + self.keep_stack_info = keep_stack_info + self.logger = logger + self.pass_foreign_args = pass_foreign_args + self.use_get_message = use_get_message + + def format(self, record: logging.LogRecord) -> str: + """ + Extract *structlog*'s `event_dict` from ``record.msg`` and format it. + + *record* has been patched by `wrap_for_formatter` first though, so the + type isn't quite right. + """ + # Make a shallow copy of the record to let other handlers/formatters + # process the original one + record = logging.makeLogRecord(record.__dict__) + + logger = getattr(record, "_logger", _SENTINEL) + meth_name = getattr(record, "_name", "__structlog_sentinel__") + + ed: ProcessorReturnValue + if logger is not _SENTINEL and meth_name != "__structlog_sentinel__": + # Both attached by wrap_for_formatter + if self.logger is not None: + logger = self.logger + meth_name = cast(str, record._name) # type:ignore[attr-defined] + + # We need to copy because it's possible that the same record gets + # processed by multiple logging formatters. LogRecord.getMessage + # would transform our dict into a str. + ed = cast(dict[str, Any], record.msg).copy() + ed["_record"] = record + ed["_from_structlog"] = True + else: + logger = self.logger + meth_name = record.levelname.lower() + ed = { + "event": ( + record.getMessage() + if self.use_get_message + else str(record.msg) + ), + "_record": record, + "_from_structlog": False, + } + + if self.pass_foreign_args: + ed["positional_args"] = record.args + + record.args = () + + # Add stack-related attributes to the event dict + if record.exc_info: + ed["exc_info"] = record.exc_info + if record.stack_info: + ed["stack_info"] = record.stack_info + + # Non-structlog allows to run through a chain to prepare it for the + # final processor (e.g. adding timestamps and log levels). + for proc in self.foreign_pre_chain or (): + ed = cast(EventDict, proc(logger, meth_name, ed)) + + # If required, unset stack-related attributes on the record copy so + # that the base implementation doesn't append stacktraces to the + # output. + if not self.keep_exc_info: + record.exc_text = None + record.exc_info = None + if not self.keep_stack_info: + record.stack_info = None + + for p in self.processors: + ed = p(logger, meth_name, ed) # type: ignore[arg-type] + + if not isinstance(ed, str): + warnings.warn( + "The last processor in ProcessorFormatter.processors must " + f"return a string, but {self.processors[-1]} returned a " + f"{type(ed)} instead.", + category=RuntimeWarning, + stacklevel=1, + ) + ed = cast(str, ed) + + record.msg = ed + + return super().format(record) + + @staticmethod + def wrap_for_formatter( + logger: logging.Logger, name: str, event_dict: EventDict + ) -> tuple[tuple[EventDict], dict[str, dict[str, Any]]]: + """ + Wrap *logger*, *name*, and *event_dict*. + + The result is later unpacked by `ProcessorFormatter` when formatting + log entries. + + Use this static method as the renderer (in other words, final + processor) if you want to use `ProcessorFormatter` in your `logging` + configuration. + """ + return (event_dict,), {"extra": {"_logger": logger, "_name": name}} + + @staticmethod + def remove_processors_meta( + _: WrappedLogger, __: str, event_dict: EventDict + ) -> EventDict: + """ + Remove ``_record`` and ``_from_structlog`` from *event_dict*. + + These keys are added to the event dictionary, before + `ProcessorFormatter`'s *processors* are run. + + .. versionadded:: 21.3.0 + """ + del event_dict["_record"] + del event_dict["_from_structlog"] + + return event_dict diff --git a/tests/test_stdlib.py b/tests/test_stdlib.py new file mode 100644 index 0000000..3669902 --- /dev/null +++ b/tests/test_stdlib.py @@ -0,0 +1,1693 @@ +# SPDX-License-Identifier: MIT OR Apache-2.0 +# This file is dual licensed under the terms of the Apache License, Version +# 2.0, and the MIT License. See the LICENSE file in the root of this +# repository for complete details. + +from __future__ import annotations + +import json +import logging +import logging.config +import os +import sys + +from collections.abc import Callable, Collection +from io import StringIO +from typing import Any +from unittest.mock import patch + +import pytest +import pytest_asyncio + +from structlog import ( + BytesLogger, + PrintLogger, + ReturnLogger, + configure, + get_context, + wrap_logger, +) +from structlog._config import _CONFIG +from structlog._log_levels import CRITICAL, DEBUG, NAME_TO_LEVEL, WARN +from structlog.dev import ConsoleRenderer +from structlog.exceptions import DropEvent +from structlog.processors import JSONRenderer, KeyValueRenderer +from structlog.stdlib import ( + AsyncBoundLogger, + BoundLogger, + ExtraAdder, + LoggerFactory, + PositionalArgumentsFormatter, + ProcessorFormatter, + _FixedFindCallerLogger, + add_log_level, + add_log_level_number, + add_logger_name, + filter_by_level, + get_logger, + recreate_defaults, + render_to_log_args_and_kwargs, + render_to_log_kwargs, +) +from structlog.testing import CapturedCall +from structlog.typing import BindableLogger, EventDict + +from .additional_frame import additional_frame +from .helpers import call_recorder, stub + + +def build_bl(logger=None, processors=None, context=None): + """ + Convenience function to build BoundLogger with sane defaults. + """ + return BoundLogger(logger or ReturnLogger(), processors, {}) + + +def return_method_name(_, method_name, __): + """ + A final renderer that returns the name of the logging method. + """ + return method_name + + +class TestLoggerFactory: + def setup_method(self, method): + """ + The stdlib logger factory modifies global state to fix caller + identification. + """ + self.original_logger = logging.getLoggerClass() + + def teardown_method(self, method): + logging.setLoggerClass(self.original_logger) + + def test_deduces_correct_name(self): + """ + The factory isn't called directly but from structlog._config so + deducing has to be slightly smarter. + """ + assert "tests.additional_frame" == ( + additional_frame(LoggerFactory()).name + ) + assert "tests.test_stdlib" == LoggerFactory()().name + + def test_ignores_frames(self): + """ + The name guesser walks up the frames until it reaches a frame whose + name is not from structlog or one of the configurable other names. + """ + + # Compute the names to __main__ so it doesn't get thrown off if people + # install plugins that alter the frames. E.g. #370 + names = set() + f = sys._getframe() + while f.f_globals["__name__"] != "__main__": + names.add(f.f_globals["__name__"].split(".", 1)[0]) + f = f.f_back + + assert ( + "__main__" + == additional_frame( + LoggerFactory(ignore_frame_names=list(names)) + ).name + ) + + def test_deduces_correct_caller(self): + """ + It will find the correct caller. + """ + logger = _FixedFindCallerLogger("test") + + file_name, _line_number, func_name = logger.findCaller()[:3] + + assert file_name == os.path.realpath(__file__) + assert func_name == "test_deduces_correct_caller" + + def test_stack_info(self): + """ + If we ask for stack_info, it will returned. + """ + logger = _FixedFindCallerLogger("test") + testing, is_, fun, stack_info = logger.findCaller(stack_info=True) # noqa: RUF059 + + assert "testing, is_, fun" in stack_info + + def test_no_stack_info_by_default(self): + """ + If we don't ask for stack_info, it won't be returned. + """ + logger = _FixedFindCallerLogger("test") + testing, is_, fun, stack_info = logger.findCaller() # noqa: RUF059 + + assert None is stack_info + + def test_find_caller(self, caplog): + """ + The caller is found. + """ + logger = LoggerFactory()() + + logger.error("Test") + + assert caplog.text.startswith( + "ERROR tests.test_stdlib:test_stdlib.py" + ) + + def test_sets_correct_logger(self): + """ + Calling LoggerFactory ensures that Logger.findCaller gets patched. + """ + LoggerFactory() + + assert logging.getLoggerClass() is _FixedFindCallerLogger + + def test_positional_argument_avoids_guessing(self): + """ + If a positional argument is passed to the factory, it's used as the + name instead of guessing. + """ + lf = LoggerFactory()("foo") + + assert "foo" == lf.name + + +class TestFilterByLevel: + def test_filters_lower_levels(self): + """ + Log entries below the current level raise a DropEvent. + """ + logger = logging.Logger(__name__) + logger.setLevel(CRITICAL) + + with pytest.raises(DropEvent): + filter_by_level(logger, "warn", {}) + + def test_passes_higher_levels(self): + """ + Log entries with higher levels are passed through unchanged. + """ + logger = logging.Logger(__name__) + logger.setLevel(WARN) + event_dict = {"event": "test"} + + assert event_dict is filter_by_level(logger, "warn", event_dict) + assert event_dict is filter_by_level(logger, "error", event_dict) + assert event_dict is filter_by_level(logger, "exception", event_dict) + + +class TestBoundLogger: + @pytest.mark.parametrize( + ("method_name"), + ["debug", "info", "warning", "error", "exception", "critical"], + ) + def test_proxies_to_correct_method(self, method_name): + """ + The basic proxied methods are proxied to the correct counterparts. + """ + bl = BoundLogger(ReturnLogger(), [return_method_name], {}) + + assert method_name == getattr(bl, method_name)("event") + + def test_proxies_to_correct_method_special_cases(self): + """ + Fatal maps to critical and warn to warning. + """ + bl = BoundLogger(ReturnLogger(), [return_method_name], {}) + + assert "warning" == bl.warn("event") + assert "critical" == bl.fatal("event") + + def test_proxies_log(self): + """ + BoundLogger.exception.log() is proxied to the appropriate method. + """ + bl = BoundLogger(ReturnLogger(), [return_method_name], {}) + + assert "critical" == bl.log(50, "event") + assert "debug" == bl.log(10, "event") + + def test_positional_args_proxied(self): + """ + Positional arguments supplied are proxied as kwarg. + """ + bl = BoundLogger(ReturnLogger(), [], {}) + _args, kwargs = bl.debug("event", "foo", bar="baz") + + assert "baz" == kwargs.get("bar") + assert ("foo",) == kwargs.get("positional_args") + + @pytest.mark.parametrize( + "attribute_name", + ["name", "level", "parent", "propagate", "handlers", "disabled"], + ) + def test_stdlib_passthrough_attributes(self, attribute_name): + """ + stdlib logger attributes are also available in stdlib BoundLogger. + """ + stdlib_logger = logging.getLogger("Test") + stdlib_logger_attribute = getattr(stdlib_logger, attribute_name) + bl = BoundLogger(stdlib_logger, [], {}) + bound_logger_attribute = getattr(bl, attribute_name) + + assert bound_logger_attribute == stdlib_logger_attribute + + @pytest.mark.parametrize( + ("method_name", "method_args"), + [ + ("addHandler", [None]), + ("removeHandler", [None]), + ("hasHandlers", None), + ("callHandlers", [None]), + ("handle", [None]), + ("setLevel", [None]), + ("getEffectiveLevel", None), + ("isEnabledFor", [None]), + ("findCaller", None), + ( + "makeRecord", + [ + "name", + "debug", + "test_func", + "1", + "test msg", + ["foo"], + False, + ], + ), + ("getChild", [None]), + ], + ) + def test_stdlib_passthrough_methods(self, method_name, method_args): + """ + stdlib logger methods are also available in stdlib BoundLogger. + """ + called_stdlib_method = [False] + + def validate(*args, **kw): + called_stdlib_method[0] = True + + stdlib_logger = logging.getLogger("Test") + stdlib_logger_method = getattr(stdlib_logger, method_name, None) + if stdlib_logger_method: + setattr(stdlib_logger, method_name, validate) + bl = BoundLogger(stdlib_logger, [], {}) + bound_logger_method = getattr(bl, method_name) + + assert bound_logger_method is not None + + if method_args: + bound_logger_method(*method_args) + else: + bound_logger_method() + + assert called_stdlib_method[0] is True + + def test_is_enabled_for(self): + """ + is_enabled_for is a snake_case alias that delegates to the wrapped + logger's isEnabledFor, for compatibility with FilteringBoundLogger. + """ + stdlib_logger = logging.getLogger("test_is_enabled_for") + stdlib_logger.setLevel(WARN) + bl = BoundLogger(stdlib_logger, [], {}) + + assert bl.is_enabled_for(WARN) is True + assert bl.is_enabled_for(DEBUG) is False + + def test_get_effective_level(self): + """ + get_effective_level is a snake_case alias that delegates to the wrapped + logger's getEffectiveLevel, for compatibility with + FilteringBoundLogger. + """ + stdlib_logger = logging.getLogger("test_get_effective_level") + stdlib_logger.setLevel(WARN) + bl = BoundLogger(stdlib_logger, [], {}) + + assert WARN == bl.get_effective_level() + + def test_exception_exc_info(self): + """ + BoundLogger.exception sets exc_info=True. + """ + bl = BoundLogger(ReturnLogger(), [], {}) + + assert ((), {"exc_info": True, "event": "event"}) == bl.exception( + "event" + ) + + def test_exception_exc_info_override(self): + """ + If *exc_info* is password to exception, it's used. + """ + bl = BoundLogger(ReturnLogger(), [], {}) + + assert ((), {"exc_info": 42, "event": "event"}) == bl.exception( + "event", exc_info=42 + ) + + def test_proxies_bind(self): + """ + Bind calls the correct bind. + """ + bl = build_bl().bind(a=42) + + assert {"a": 42} == get_context(bl) + + def test_proxies_new(self): + """ + Newcalls the correct new. + """ + bl = build_bl().bind(a=42).new(b=23) + + assert {"b": 23} == get_context(bl) + + def test_proxies_unbind(self): + """ + Unbind calls the correct unbind. + """ + bl = build_bl().bind(a=42).unbind("a") + + assert {} == get_context(bl) + + def test_proxies_try_unbind(self): + """ + try_unbind calls the correct try_unbind. + """ + bl = build_bl().bind(a=42).try_unbind("a", "b") + + assert {} == get_context(bl) + + @pytest.mark.parametrize( + "meth", ["debug", "info", "warning", "error", "critical"] + ) + async def test_async_log_methods(self, meth, cl): + """ + Async methods log async. + """ + bl = build_bl(cl, processors=[]) + + await getattr(bl, f"a{meth}")("Async!") + + assert [ + CapturedCall(method_name=meth, args=(), kwargs={"event": "Async!"}) + ] == cl.calls + + async def test_async_log_methods_special_cases(self, cl): + """ + afatal maps to critical. + """ + bl = build_bl(cl, processors=[]) + + await bl.afatal("Async!") + + assert [ + CapturedCall( + method_name="critical", args=(), kwargs={"event": "Async!"} + ) + ] == cl.calls + + async def test_alog(self, cl): + """ + Alog logs async at the correct level. + """ + bl = build_bl(cl, processors=[]) + + await bl.alog(logging.INFO, "foo %s", "bar") + + assert [ + CapturedCall( + method_name="info", + args=(), + kwargs={"positional_args": ("bar",), "event": "foo %s"}, + ) + ] == cl.calls + + async def test_aexception_exc_info_true(self, cl): + """ + aexception passes current exc_info into dispatch. + """ + bl = build_bl(cl, processors=[]) + + try: + raise ValueError(42) + except ValueError as e: + await bl.aexception("oops") + exc = e + + (cc,) = cl.calls + + assert isinstance(cc[2]["exc_info"], tuple) + assert exc == cc[2]["exc_info"][1] + + async def test_aexception_exc_info_explicit(self, cl): + """ + In aexception, if exc_info isn't missing or True, leave it be. + """ + bl = build_bl(cl, processors=[]) + + obj = object() + + await bl.aexception("ooops", exc_info=obj) + + assert obj is cl.calls[0].kwargs["exc_info"] + + +class TestPositionalArgumentsFormatter: + def test_formats_tuple(self): + """ + Positional arguments as simple types are rendered. + """ + formatter = PositionalArgumentsFormatter() + event_dict = formatter( + None, + None, + {"event": "%d %d %s", "positional_args": (1, 2, "test")}, + ) + + assert "1 2 test" == event_dict["event"] + assert "positional_args" not in event_dict + + def test_formats_dict(self): + """ + Positional arguments as dict are rendered. + """ + formatter = PositionalArgumentsFormatter() + event_dict = formatter( + None, + None, + {"event": "%(foo)s bar", "positional_args": ({"foo": "bar"},)}, + ) + + assert "bar bar" == event_dict["event"] + assert "positional_args" not in event_dict + + def test_positional_args_retained(self): + """ + Positional arguments are retained if remove_positional_args + argument is set to False. + """ + formatter = PositionalArgumentsFormatter(remove_positional_args=False) + positional_args = (1, 2, "test") + event_dict = formatter( + None, + None, + {"event": "%d %d %s", "positional_args": positional_args}, + ) + + assert "positional_args" in event_dict + assert positional_args == event_dict["positional_args"] + + def test_nop_no_args(self): + """ + If no positional args are passed, nothing happens. + """ + formatter = PositionalArgumentsFormatter() + + assert {} == formatter(None, None, {}) + + def test_args_removed_if_empty(self): + """ + If remove_positional_args is True and positional_args is (), still + remove them. + + Regression test for https://github.com/hynek/structlog/issues/82. + """ + formatter = PositionalArgumentsFormatter() + + assert {} == formatter(None, None, {"positional_args": ()}) + + +class TestAddLogLevelNumber: + @pytest.mark.parametrize(("level", "number"), NAME_TO_LEVEL.items()) + def test_log_level_number_added(self, level, number): + """ + The log level number is added to the event dict. + """ + event_dict = add_log_level_number(None, level, {}) + + assert number == event_dict["level_number"] + + +class TestAddLogLevel: + def test_log_level_added(self): + """ + The log level is added to the event dict. + """ + event_dict = add_log_level(None, "error", {}) + + assert "error" == event_dict["level"] + + @pytest.mark.parametrize( + ("alias", "normalized"), [("warn", "warning"), ("exception", "error")] + ) + def test_log_level_alias_normalized(self, alias, normalized): + """ + The normalized name of the log level is added to the event dict. + """ + event_dict = add_log_level(None, alias, {}) + + assert normalized == event_dict["level"] + + +@pytest.fixture(name="make_log_record") +def _make_log_record(): + """ + A LogRecord factory. + """ + + def create_log_record(**kwargs): + defaults = { + "name": "sample-name", + "level": logging.INFO, + "pathname": None, + "lineno": None, + "msg": "sample-message", + "args": [], + "exc_info": None, + } + defaults.update(kwargs) + return logging.LogRecord(**defaults) + + return create_log_record + + +class TestAddLoggerName: + def test_logger_name_added(self): + """ + The logger name is added to the event dict. + """ + name = "sample-name" + logger = logging.getLogger(name) + event_dict = add_logger_name(logger, None, {}) + + assert name == event_dict["logger"] + + def test_logger_name_added_with_record(self, make_log_record): + """ + The logger name is deduced from the LogRecord if provided. + """ + name = "sample-name" + record = make_log_record(name=name) + event_dict = add_logger_name(None, None, {"_record": record}) + + assert name == event_dict["logger"] + + def test_logger_name_added_with_bytes_logger(self): + """ + add_logger_name works with BytesLogger that has a name attribute. + """ + name = "sample-name" + logger = BytesLogger(name=name) + event_dict = add_logger_name(logger, None, {}) + + assert name == event_dict["logger"] + + def test_logger_name_none_with_unnamed_bytes_logger(self): + """ + add_logger_name works with BytesLogger without a name, returning None. + """ + logger = BytesLogger() + event_dict = add_logger_name(logger, None, {}) + + assert event_dict["logger"] is None + + +def extra_dict() -> dict[str, Any]: + """ + A dict to be passed in the `extra` parameter of the `logging` module's log + methods. + """ + return { + "this": "is", + "some": "extra values", + "x_int": 4, + "x_bool": True, + } + + +@pytest.fixture(name="extra_dict") +def extra_dict_fixture(): + return extra_dict() + + +class TestExtraAdder: + @pytest.mark.parametrize( + ("allow", "misses"), + [ + (None, None), + ({}, None), + *[({key}, None) for key in extra_dict()], + ({"missing"}, {"missing"}), + ({"missing", "keys"}, {"missing"}), + ({"this", "x_int"}, None), + ], + ) + def test_add_extra( + self, + make_log_record: Callable[[], logging.LogRecord], + extra_dict: dict[str, Any], + allow: Collection[str] | None, + misses: set[str] | None, + ): + """ + Extra attributes of a LogRecord object are added to the event dict. + """ + record: logging.LogRecord = make_log_record() + record.__dict__.update(extra_dict) + event_dict = {"_record": record, "ed_key": "ed_value"} + expected = self._copy_allowed(event_dict, extra_dict, allow) + + if allow is None: + actual = ExtraAdder()(None, None, event_dict) + assert expected == actual + actual = ExtraAdder(allow)(None, None, event_dict) + assert expected == actual + if misses: + assert misses.isdisjoint(expected.keys()) + + def test_no_record(self): + """ + If the event_dict has no LogRecord, do nothing. + """ + actual = ExtraAdder()(None, None, {}) + + assert {} == actual + + @pytest.mark.parametrize( + ("allow", "misses"), + [ + (None, None), + ({}, None), + *[({key}, None) for key in extra_dict()], + ({"missing"}, {"missing"}), + ({"missing", "keys"}, {"missing"}), + ({"this", "x_int"}, None), + ], + ) + def test_add_extra_e2e( + self, + extra_dict: dict[str, Any], + allow: Collection[str] | None, + misses: set[str] | None, + ): + """ + Values passed in the `extra` parameter of the `logging` module's log + methods pass through to log output. + """ + logger = logging.Logger(sys._getframe().f_code.co_name) + string_io = StringIO() + handler = logging.StreamHandler(string_io) + formatter = ProcessorFormatter( + foreign_pre_chain=[ExtraAdder(allow)], + processors=[JSONRenderer()], + ) + handler.setFormatter(formatter) + handler.setLevel(0) + logger.addHandler(handler) + logger.setLevel(0) + logging.warning("allow = %s", allow) # noqa: LOG015 + + event_dict = {"event": "Some text"} + expected = self._copy_allowed(event_dict, extra_dict, allow) + + logger.info("Some %s", "text", extra=extra_dict) + actual = { + key: value + for key, value in json.loads(string_io.getvalue()).items() + if not key.startswith("_") + } + + assert expected == actual + if misses: + assert misses.isdisjoint(expected.keys()) + + @classmethod + def _copy_allowed( + cls, + event_dict: EventDict, + extra_dict: dict[str, Any], + allow: Collection[str] | None, + ) -> EventDict: + if allow is None: + return {**event_dict, **extra_dict} + + return { + **event_dict, + **{ + key: value for key, value in extra_dict.items() if key in allow + }, + } + + +@pytest.fixture(name="stdlib_logger") +def _stdlib_logger(): + logger = logging.getLogger("test_logger") + logger.setLevel(logging.DEBUG) + + yield logger + + logging.basicConfig() + + +class TestRenderToLogArgsAndKwargs: + def test_default(self, stdlib_logger: logging.Logger): + """ + Passes `event` key from `event_dict` in the first positional argument + and handles otherwise empty `event_dict`. + """ + method_name = "debug" + event = "message" + args, kwargs = render_to_log_args_and_kwargs( + stdlib_logger, method_name, {"event": event} + ) + + assert (event,) == args + assert {} == kwargs + + with patch.object(stdlib_logger, "_log") as mock_log: + getattr(stdlib_logger, method_name)(*args, **kwargs) + + mock_log.assert_called_once_with(logging.DEBUG, event, ()) + + def test_pass_remaining_event_dict_as_extra( + self, stdlib_logger: logging.Logger, event_dict: dict[str, Any] + ): + """ + Passes remaining `event_dict` as `extra`. + """ + expected_extra = event_dict.copy() + + method_name = "info" + event = "message" + event_dict["event"] = event + + args, kwargs = render_to_log_args_and_kwargs( + stdlib_logger, method_name, event_dict + ) + + assert (event,) == args + assert {"extra": expected_extra} == kwargs + + with patch.object(stdlib_logger, "_log") as mock_log: + getattr(stdlib_logger, method_name)(*args, **kwargs) + + mock_log.assert_called_once_with( + logging.INFO, event, (), extra=expected_extra + ) + + def test_pass_positional_args_from_event_dict_as_args( + self, stdlib_logger: logging.Logger, event_dict: dict[str, Any] + ): + """ + Passes items from "positional_args" key from `event_dict` as positional + arguments. + """ + expected_extra = event_dict.copy() + + method_name = "warning" + event = "message: a = %s, b = %d" + positional_args = ("foo", 123) + event_dict["event"] = event + event_dict["positional_args"] = positional_args + + args, kwargs = render_to_log_args_and_kwargs( + stdlib_logger, method_name, event_dict + ) + + assert (event, *(positional_args)) == args + assert {"extra": expected_extra} == kwargs + + with patch.object(stdlib_logger, "_log") as mock_log: + getattr(stdlib_logger, method_name)(*args, **kwargs) + + mock_log.assert_called_once_with( + logging.WARNING, event, positional_args, extra=expected_extra + ) + + def test_pass_kwargs_from_event_dict_as_kwargs( + self, stdlib_logger: logging.Logger, event_dict: dict[str, Any] + ): + """ + Passes "exc_info", "stack_info", and "stacklevel" keys from `event_dict` + as keyword arguments. + """ + expected_extra = event_dict.copy() + + method_name = "info" + event = "message" + exc_info = True + stack_info = False + stacklevel = 2 + event_dict["event"] = event + event_dict["exc_info"] = exc_info + event_dict["stack_info"] = stack_info + event_dict["stacklevel"] = stacklevel + + args, kwargs = render_to_log_args_and_kwargs( + stdlib_logger, method_name, event_dict + ) + + assert (event,) == args + assert { + "exc_info": exc_info, + "stack_info": stack_info, + "stacklevel": stacklevel, + "extra": expected_extra, + } == kwargs + + with patch.object(stdlib_logger, "_log") as mock_log: + getattr(stdlib_logger, method_name)(*args, **kwargs) + + mock_log.assert_called_once_with( + logging.INFO, + event, + (), + exc_info=exc_info, + stack_info=stack_info, + stacklevel=stacklevel, + extra=expected_extra, + ) + + def test_integration( + self, stdlib_logger: logging.Logger, event_dict: dict[str, Any] + ): + """ + `render_to_log_args_and_kwargs` with a wrapped logger calls the stdlib + logger correctly. + + Reserved stdlib keyword arguments are in `logging.Logger._log`. + https://github.com/python/cpython/blob/60403a5409ff2c3f3b07dd2ca91a7a3e096839c7/Lib/logging/__init__.py#L1640 + """ + event = "message: a = %s, b = %d" + arg_1 = "foo" + arg_2 = 123 + exc_info = False + stack_info = True + stacklevel = 3 + + struct_logger = wrap_logger( + stdlib_logger, + processors=[render_to_log_args_and_kwargs], + wrapper_class=BoundLogger, + ) + + with patch.object(stdlib_logger, "_log") as mock_log: + struct_logger.info( + event, + arg_1, + arg_2, + exc_info=exc_info, + stack_info=stack_info, + stacklevel=stacklevel, + **event_dict, + ) + + mock_log.assert_called_once_with( + logging.INFO, + event, + (arg_1, arg_2), + exc_info=exc_info, + stack_info=stack_info, + stacklevel=stacklevel, + extra=event_dict, + ) + + +class TestRenderToLogKwargs: + def test_default(self, stdlib_logger): + """ + Translates `event` to `msg` and handles otherwise empty `event_dict`s. + """ + d = render_to_log_kwargs(None, None, {"event": "message"}) + + assert {"msg": "message", "extra": {}} == d + + # now check stdlib logger likes those kwargs + with patch.object(stdlib_logger, "_log") as mock_log: + stdlib_logger.info(**d) + + mock_log.assert_called_once_with(logging.INFO, "message", (), extra={}) + + def test_add_extra_event_dict(self, event_dict, stdlib_logger): + """ + Adds all remaining data from `event_dict` into `extra`. + """ + event_dict["event"] = "message" + d = render_to_log_kwargs(None, None, event_dict) + + assert {"msg": "message", "extra": event_dict} == d + + # now check stdlib logger likes those kwargs + with patch.object(stdlib_logger, "_log") as mock_log: + stdlib_logger.info(**d) + + mock_log.assert_called_once_with( + logging.INFO, "message", (), extra=event_dict + ) + + def test_handles_special_kw(self, event_dict, stdlib_logger): + """ + "exc_info", "stack_info", and "stacklevel" aren't passed as extras. + + Cf. https://github.com/hynek/structlog/issues/424 + """ + del event_dict["a"] # needs a repr + event_dict["event"] = "message" + + event_dict["exc_info"] = True + event_dict["stack_info"] = False + event_dict["stacklevel"] = 1 + event_dict["stackLevel"] = 1 # not a reserved kw + + d = render_to_log_kwargs(None, None, event_dict) + expected = { + "msg": "message", + "exc_info": True, + "stack_info": False, + "stacklevel": 1, + "extra": { + "b": [3, 4], + "x": 7, + "y": "test", + "z": (1, 2), + "stackLevel": 1, + }, + } + + assert expected == d + + # now check stdlib logger likes those kwargs + with patch.object(stdlib_logger, "_log") as mock_log: + stdlib_logger.info(**d) + + expected.pop("msg") + mock_log.assert_called_once_with( + logging.INFO, "message", (), **expected + ) + + def test_integration_special_kw(self, event_dict, stdlib_logger): + """ + render_to_log_kwargs with a wrapped logger calls the stdlib logger + correctly + + reserved stdlib keywords are in logging.Logger._log + https://github.com/python/cpython/blob/ae7b17673f29efe17b416cbcfbf43b5b3ff5977c/Lib/logging/__init__.py#L1632 + """ + expected = { + "msg": "message", + "exc_info": True, + "stack_info": False, + "stacklevel": 1, + "extra": {**event_dict}, + } + + event_dict["exc_info"] = True + event_dict["stack_info"] = False + event_dict["stacklevel"] = 1 + + struct_logger = wrap_logger( + stdlib_logger, + processors=[render_to_log_kwargs], + ) + + # now check struct logger passes those kwargs to stdlib + with patch.object(stdlib_logger, "_log") as mock_log: + struct_logger.info("message", **event_dict) + + expected.pop("msg") + mock_log.assert_called_once_with( + logging.INFO, "message", (), **expected + ) + + +@pytest.fixture(name="configure_for_processor_formatter") +def _configure_for_processor_formatter(): + """ + Configure structlog to use ProcessorFormatter. + + Reset logging setting after the test (structlog is reset automatically + before all tests). + """ + configure( + processors=[add_log_level, ProcessorFormatter.wrap_for_formatter], + logger_factory=LoggerFactory(), + wrapper_class=BoundLogger, + ) + + yield + + logging.basicConfig() + + +def configure_logging( + pre_chain, + logger=None, + pass_foreign_args=False, + renderer=ConsoleRenderer(colors=False), # noqa: B008 +): + """ + Configure logging to use ProcessorFormatter. + + Return a list that is filled with event dicts form calls. + """ + event_dicts = [] + + def capture(_, __, ed): + event_dicts.append(ed.copy()) + + return ed + + logging.config.dictConfig( + { + "version": 1, + "disable_existing_loggers": False, + "formatters": { + "plain": { + "()": ProcessorFormatter, + "processors": [ + capture, + ProcessorFormatter.remove_processors_meta, + renderer, + ], + "foreign_pre_chain": pre_chain, + "format": "%(message)s [in %(funcName)s]", + "logger": logger, + "pass_foreign_args": pass_foreign_args, + } + }, + "handlers": { + "default": { + "level": "DEBUG", + "class": "logging.StreamHandler", + "formatter": "plain", + } + }, + "loggers": { + "": { + "handlers": ["default"], + "level": "DEBUG", + "propagate": True, + } + }, + } + ) + + return event_dicts + + +@pytest.mark.usefixtures("configure_for_processor_formatter") +class TestProcessorFormatter: + """ + These are all integration tests because they're all about integration. + """ + + def test_foreign_delegate(self, capsys): + """ + If foreign_pre_chain is None, non-structlog log entries are delegated + to logging. The processor chain's event dict is invoked with + `_from_structlog=False` + """ + calls = configure_logging(None) + + logging.getLogger().warning("foo") + + assert ("", "foo [in test_foreign_delegate]\n") == capsys.readouterr() + assert calls[0]["_from_structlog"] is False + assert isinstance(calls[0]["_record"], logging.LogRecord) + + def test_clears_args(self, capsys): + """ + We render our log records before sending it back to logging. Therefore + we must clear `LogRecord.args` otherwise the user gets an + `TypeError: not all arguments converted during string formatting.` if + they use positional formatting in stdlib logging. + """ + configure_logging(None) + + logging.getLogger().warning("hello %s.", "world") + + assert ( + "", + "hello world. [in test_clears_args]\n", + ) == capsys.readouterr() + + def test_pass_foreign_args_true_sets_positional_args_key(self): + """ + If `pass_foreign_args` is `True` we set the `positional_args` key in + the `event_dict` before clearing args. + """ + test_processor = call_recorder(lambda _, __, event_dict: event_dict) + configure_logging((test_processor,), pass_foreign_args=True) + + positional_args = {"foo": "bar"} + logging.getLogger().info("okay %(foo)s", positional_args) + + event_dict = test_processor.call_args_list[0].args[2] + + assert "positional_args" in event_dict + assert positional_args == event_dict["positional_args"] + + def test_log_dict(self, capsys): + """ + dicts can be logged with std library loggers. + """ + configure_logging(None) + + logging.getLogger().warning({"foo": "bar"}) + + assert ( + "", + "{'foo': 'bar'} [in test_log_dict]\n", + ) == capsys.readouterr() + + def test_foreign_pre_chain(self, capsys): + """ + If foreign_pre_chain is an iterable, it's used to pre-process + non-structlog log entries. + """ + configure_logging([add_log_level]) + + logging.getLogger().warning("foo") + + assert ( + "", + "[warning ] foo [in test_foreign_pre_chain]\n", + ) == capsys.readouterr() + + def test_foreign_pre_chain_add_logger_name(self, capsys): + """ + foreign_pre_chain works with add_logger_name processor. + """ + configure_logging((add_logger_name,)) + + logging.getLogger("sample-name").warning("foo") + + assert ( + "", + ( + "foo [sample-name] [in test_foreign_pr" + "e_chain_add_logger_name]\n" + ), + ) == capsys.readouterr() + + def test_foreign_chain_can_pass_dictionaries_without_excepting( + self, capsys + ): + """ + If a foreign logger passes a dictionary to a logging function, + check we correctly identify that it did not come from structlog. + """ + configure_logging(None) + configure( + processors=[ProcessorFormatter.wrap_for_formatter], + logger_factory=LoggerFactory(), + wrapper_class=BoundLogger, + ) + + logging.getLogger().warning({"foo": "bar"}) + + assert ( + "", + ( + "{'foo': 'bar'} [in " + "test_foreign_chain_can_pass_dictionaries_without_excepting]\n" + ), + ) == capsys.readouterr() + + def test_foreign_pre_chain_gets_exc_info(self): + """ + If non-structlog record contains exc_info, foreign_pre_chain functions + have access to it. + """ + test_processor = call_recorder(lambda _, __, event_dict: event_dict) + configure_logging((test_processor,), renderer=KeyValueRenderer()) + + try: + raise RuntimeError("oh no") + except Exception: + logging.getLogger().exception("okay") + + event_dict = test_processor.call_args_list[0].args[2] + + assert "exc_info" in event_dict + assert isinstance(event_dict["exc_info"], tuple) + + def test_foreign_pre_chain_sys_exc_info(self): + """ + If a foreign_pre_chain function accesses sys.exc_info(), + ProcessorFormatter should not have changed it. + """ + + class MyError(Exception): + pass + + def add_excinfo(logger, log_method, event_dict): + event_dict["exc_info"] = sys.exc_info() + return event_dict + + test_processor = call_recorder(lambda _, __, event_dict: event_dict) + configure_logging( + (add_excinfo, test_processor), renderer=KeyValueRenderer() + ) + + try: + raise MyError("oh no") + except Exception: + logging.getLogger().error("okay") + + event_dict = test_processor.call_args_list[0].args[2] + + assert MyError is event_dict["exc_info"][0] + + def test_other_handlers_get_original_record(self): + """ + Logging handlers that come after the handler with ProcessorFormatter + should receive original, unmodified record. + """ + configure_logging(None) + + handler1 = logging.StreamHandler() + handler1.setFormatter(ProcessorFormatter(JSONRenderer())) + handler2 = stub( + handle=call_recorder(lambda record: None), + level=logging.INFO, + ) + logger = logging.getLogger() + logger.addHandler(handler1) + logger.addHandler(handler2) + + logger.info("meh") + + assert 1 == len(handler2.handle.call_args_list) + + handler2_record = handler2.handle.call_args_list[0].args[0] + + assert "meh" == handler2_record.msg + + @pytest.mark.parametrize("keep", [True, False]) + def test_formatter_unsets_exc_info(self, capsys, keep): + """ + Stack traces doesn't get printed outside of the json document when + keep_exc_info are set to False but preserved if set to True. + """ + configure_logging(None) + logger = logging.getLogger() + + def format_exc_info_fake(logger, name, event_dict): + del event_dict["exc_info"] + event_dict["exception"] = "Exception!" + return event_dict + + formatter = ProcessorFormatter( + processor=JSONRenderer(), + keep_stack_info=keep, + keep_exc_info=keep, + foreign_pre_chain=[format_exc_info_fake], + ) + logger.handlers[0].setFormatter(formatter) + + try: + raise RuntimeError("oh no") + except Exception: + logging.getLogger().exception("seen worse") + + out, err = capsys.readouterr() + + assert "" == out + + if keep is False: + assert ( + '{"event": "seen worse", "exception": "Exception!"}\n' + ) == err + else: + assert "Traceback (most recent call last):" in err + + @pytest.mark.parametrize("keep", [True, False]) + def test_formatter_unsets_stack_info(self, capsys, keep): + """ + Stack traces doesn't get printed outside of the json document when + keep_stack_info are set to False but preserved if set to True. + """ + configure_logging(None) + logger = logging.getLogger() + + formatter = ProcessorFormatter( + processor=JSONRenderer(), + keep_stack_info=keep, + keep_exc_info=keep, + foreign_pre_chain=[], + ) + logger.handlers[0].setFormatter(formatter) + + logging.getLogger().warning("have a stack trace", stack_info=True) + + out, err = capsys.readouterr() + + assert "" == out + + if keep is False: + assert 1 == err.count("Stack (most recent call last):") + else: + assert 2 == err.count("Stack (most recent call last):") + + def test_native(self, capsys): + """ + If the log entry comes from structlog, it's unpackaged and processed. + """ + eds = configure_logging(None) + + get_logger().warning("foo") + + assert ( + "", + "[warning ] foo [in test_native]\n", + ) == capsys.readouterr() + assert eds[0]["_from_structlog"] is True + assert isinstance(eds[0]["_record"], logging.LogRecord) + + def test_native_logger(self, capsys): + """ + If the log entry comes from structlog, it's unpackaged and processed. + """ + logger = logging.getLogger() + eds = configure_logging(None, logger=logger) + + get_logger().warning("foo") + + assert ( + "", + "[warning ] foo [in test_native_logger]\n", + ) == capsys.readouterr() + assert eds[0]["_from_structlog"] is True + assert isinstance(eds[0]["_record"], logging.LogRecord) + + def test_foreign_pre_chain_filter_by_level(self, capsys): + """ + foreign_pre_chain works with filter_by_level processor. + """ + logger = logging.getLogger() + configure_logging([filter_by_level], logger=logger) + configure( + processors=[ProcessorFormatter.wrap_for_formatter], + logger_factory=LoggerFactory(), + wrapper_class=BoundLogger, + ) + + logger.warning("foo") + + assert ( + "", + "foo [in test_foreign_pre_chain_filter_by_level]\n", + ) == capsys.readouterr() + + def test_processor_and_processors(self): + """ + Passing both processor and processors raises a TypeError. + """ + with pytest.raises(TypeError, match="mutually exclusive"): + ProcessorFormatter(processor=1, processors=[1]) + + def test_no_renderer(self): + """ + Passing neither processor nor processors raises a TypeError. + """ + with pytest.raises(TypeError, match="must be passed"): + ProcessorFormatter() + + def test_remove_processors_meta(self): + """ + remove_processors_meta removes _record and _from_structlog. And only + them. + """ + assert {"foo": "bar"} == ProcessorFormatter.remove_processors_meta( + None, + None, + {"foo": "bar", "_record": "foo", "_from_structlog": True}, + ) + + def test_non_string_message_warning(self): + """ + A warning is raised if the last processor in + ProcessorFormatter.processors doesn't return a string. + """ + configure_logging(None) + logger = logging.getLogger() + + formatter = ProcessorFormatter( + processors=[lambda *args, **kwargs: {"foo": "bar"}], + ) + logger.handlers[0].setFormatter(formatter) + + with pytest.warns( + RuntimeWarning, + match="The last processor in ProcessorFormatter.processors must return a string", + ): + logger.info("baz") + + def test_logrecord_exc_info(self): + """ + LogRecord.exc_info is set consistently for structlog and non-structlog + log records. + """ + configure_logging(None) + + # This doesn't test ProcessorFormatter itself directly, but it's + # relevant to setups where ProcessorFormatter is used, i.e. where + # handlers will receive LogRecord objects that come from both structlog + # and non-structlog loggers. + + records: dict[str, logging.LogRecord] = {} + + class DummyHandler(logging.Handler): + def emit(self, record): + # Don't do anything; just store the record in the records dict + # by its message, so we can assert things about it. + if isinstance(record.msg, dict): + records[record.msg["event"]] = record + else: + records[record.msg] = record + + stdlib_logger = logging.getLogger() + structlog_logger = get_logger() + + # It doesn't matter which logger we add the handler to here. + stdlib_logger.addHandler(DummyHandler()) + + try: + raise Exception("foo") + except Exception: + stdlib_logger.exception("bar") + structlog_logger.exception("baz") + + stdlib_record = records.pop("bar") + + assert "bar" == stdlib_record.msg + assert stdlib_record.exc_info + assert Exception is stdlib_record.exc_info[0] + assert ("foo",) == stdlib_record.exc_info[1].args + + structlog_record = records.pop("baz") + + assert "baz" == structlog_record.msg["event"] + assert True is structlog_record.msg["exc_info"] + assert structlog_record.exc_info + assert Exception is structlog_record.exc_info[0] + assert ("foo",) == structlog_record.exc_info[1].args + + assert not records + + def test_use_get_message_false(self): + """ + If use_get_message_is False, the event is obtained using + str(record.msg) instead of calling record.getMessage. That means + positional formatting is not performed. + """ + event_dicts = [] + + def capture(_, __, ed): + event_dicts.append(ed.copy()) + + return str(ed) + + proc = ProcessorFormatter(processors=[capture], use_get_message=False) + + record = logging.LogRecord( + "foo", + logging.INFO, + "path.py", + 42, + "le msg: %s", + ("keep separate",), + None, + ) + + assert proc.format(record) + assert "le msg: %s" == event_dicts[0]["event"] + + +@pytest_asyncio.fixture(name="abl") +async def _abl(cl): + return AsyncBoundLogger(cl, context={}, processors=[]) + + +class TestAsyncBoundLogger: + def test_sync_bl(self, abl, cl): + """ + AsyncBoungLogger.sync_bl works outside of loops. + """ + abl.sync_bl.info("test") + + assert [ + CapturedCall(method_name="info", args=(), kwargs={"event": "test"}) + ] == cl.calls + + @pytest.mark.asyncio + async def test_protocol(self, abl): + """ + AsyncBoundLogger is a proper BindableLogger. + """ + assert isinstance(abl, BindableLogger) + + @pytest.mark.asyncio + async def test_correct_levels(self, abl, cl, stdlib_log_method): + """ + The proxy methods call the correct upstream methods. + """ + await getattr(abl.bind(foo="bar"), stdlib_log_method)("42") + + aliases = {"warn": "warning"} + + expect = aliases.get(stdlib_log_method, stdlib_log_method) + + assert expect == cl.calls[0].method_name + + @pytest.mark.asyncio + async def test_correct_level_fatal(self, abl, cl): + """ + fatal, that I have no idea why we support, maps to critical. + """ + await abl.bind(foo="bar").fatal("42") + + assert "critical" == cl.calls[0].method_name + + @pytest.mark.asyncio + async def test_log_method(self, abl, cl): + """ + The `log` method is proxied too. + """ + await abl.bind(foo="bar").log(logging.ERROR, "42") + + assert "error" == cl.calls[0].method_name + + @pytest.mark.asyncio + async def test_exception(self, abl, cl): + """ + `exception` makes sure 'exc_info" is set, if it's not set already. + """ + try: + raise ValueError("omg") + except ValueError: + await abl.exception("oops") + + ei = cl.calls[0].kwargs["exc_info"] + + assert ValueError is ei[0] + assert ("omg",) == ei[1].args + + @pytest.mark.asyncio + async def test_exception_do_not_overwrite(self, abl, cl): + """ + `exception` leaves exc_info be, if it's set. + """ + o1 = object() + o2 = object() + o3 = object() + + try: + raise ValueError("omg") + except ValueError: + await abl.exception("oops", exc_info=(o1, o2, o3)) + + ei = cl.calls[0].kwargs["exc_info"] + assert (o1, o2, o3) == ei + + @pytest.mark.asyncio + async def test_bind_unbind(self, cl): + """ + new/bind/unbind/try_unbind are correctly propagated. + """ + l1 = AsyncBoundLogger(cl, context={}, processors=[]) + + l2 = l1.bind(x=42) + + assert l1 is not l2 + assert l1.sync_bl is not l2.sync_bl + assert {} == l1._context + assert {"x": 42} == l2._context + + l3 = l2.new(y=23) + + assert l2 is not l3 + assert l2.sync_bl is not l3.sync_bl + assert {"y": 23} == l3._context + + l4 = l3.unbind("y") + + assert {} == l4._context + assert l3 is not l4 + + # N.B. x isn't bound anymore. + l5 = l4.try_unbind("x") + + assert {} == l5._context + assert l4 is not l5 + + @pytest.mark.asyncio + async def test_integration(self, capsys): + """ + Configure and log an actual entry. + """ + + configure( + processors=[add_log_level, JSONRenderer()], + logger_factory=PrintLogger, + wrapper_class=AsyncBoundLogger, + cache_logger_on_first_use=True, + ) + + logger = get_logger() + + await logger.bind(foo="bar").info("baz", x="42") + + assert { + "foo": "bar", + "x": "42", + "event": "baz", + "level": "info", + } == json.loads(capsys.readouterr().out) + + +@pytest.mark.parametrize("log_level", [None, 45]) +def test_recreate_defaults(log_level): + """ + Recreate defaults configures structlog and -- if asked -- logging. + """ + logging.basicConfig( + stream=sys.stderr, + level=1, + force=True, + ) + + recreate_defaults(log_level=log_level) + + assert BoundLogger is _CONFIG.default_wrapper_class + assert dict is _CONFIG.default_context_class + assert isinstance(_CONFIG.logger_factory, LoggerFactory) + + log = get_logger().bind() + if log_level is not None: + assert log_level == log.getEffectiveLevel() + else: + assert 1 == log.getEffectiveLevel()