diff --git a/CHANGELOG.md b/CHANGELOG.md index cfdd8222..4d1ddca1 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,14 +15,19 @@ You can find our backwards-compatibility policy [here](https://github.com/hynek/ ## [Unreleased](https://github.com/hynek/structlog/compare/23.2.0...HEAD) +### Added + +- `structlog.processors.AddCallingClassPath()` added, which will attempt to determine the calling class path and add it as `class_path` to the event dict. Takes an optional `levels` `list`|`set` to limit which `logging.LEVEL` to include the addition in. + ### Fixed +- `AsyncBoundLogger` now properly supports callsite parameters. + - 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 `BoundLoggerLazyProxy` (in other words: before anything is bound to a bound logger). - ## [23.2.0](https://github.com/hynek/structlog/compare/23.1.0...23.2.0) - 2023-10-09 ### Removed diff --git a/docs/api.rst b/docs/api.rst index 5a911533..3b05a8e8 100644 --- a/docs/api.rst +++ b/docs/api.rst @@ -278,6 +278,8 @@ API Reference .. autoclass:: CallsiteParameterAdder +.. autoclass:: AddCallingClassPath + `structlog.stdlib` Module ------------------------- diff --git a/src/structlog/_frames.py b/src/structlog/_frames.py index 7a5fb6c3..51346d2f 100644 --- a/src/structlog/_frames.py +++ b/src/structlog/_frames.py @@ -11,6 +11,7 @@ from io import StringIO from types import FrameType +from .contextvars import _ASYNC_CALLING_STACK from .typing import ExcInfo @@ -50,7 +51,7 @@ def _find_first_app_frame_and_name( tuple of (frame, name) """ ignores = ["structlog"] + (additional_ignores or []) - f = sys._getframe() + f = _ASYNC_CALLING_STACK.get(sys._getframe()) name = f.f_globals.get("__name__") or "?" while any(tuple(name.startswith(i) for i in ignores)): if f.f_back is None: diff --git a/src/structlog/_log_levels.py b/src/structlog/_log_levels.py index b2e721b6..be132fcb 100644 --- a/src/structlog/_log_levels.py +++ b/src/structlog/_log_levels.py @@ -17,6 +17,7 @@ from typing import Any, Callable from ._base import BoundLoggerBase +from .contextvars import _ASYNC_CALLING_STACK from .typing import EventDict, FilteringBoundLogger @@ -91,16 +92,26 @@ def exception( async def aexception( self: FilteringBoundLogger, event: str, *args: Any, **kw: Any ) -> Any: + """ + .. versionchanged:: 23.3.0 + Callsite parameters are now also collected under asyncio. + """ # Exception info has to be extracted this early, because it is no longer # available once control is passed to the executor. if kw.get("exc_info", True) is True: kw["exc_info"] = sys.exc_info() + scs_token = _ASYNC_CALLING_STACK.set(sys._getframe().f_back) # type: ignore[arg-type] ctx = contextvars.copy_context() - return await asyncio.get_running_loop().run_in_executor( - None, - lambda: ctx.run(lambda: self.error(event, *args, **kw)), - ) + try: + runner = await asyncio.get_running_loop().run_in_executor( + None, + lambda: ctx.run(lambda: self.error(event, *args, **kw)), + ) + finally: + _ASYNC_CALLING_STACK.reset(scs_token) + + return runner def make_filtering_bound_logger(min_level: int) -> type[FilteringBoundLogger]: @@ -170,16 +181,24 @@ def meth(self: Any, event: str, *args: Any, **kw: Any) -> Any: return self._proxy_to_logger(name, event % args, **kw) async def ameth(self: Any, event: str, *args: Any, **kw: Any) -> Any: + """ + .. versionchanged:: 23.3.0 + Callsite parameters are now also collected under asyncio. + """ if args: event = event % args + scs_token = _ASYNC_CALLING_STACK.set(sys._getframe().f_back) # type: ignore[arg-type] ctx = contextvars.copy_context() - await asyncio.get_running_loop().run_in_executor( - None, - lambda: ctx.run( - lambda: self._proxy_to_logger(name, event, **kw) - ), - ) + try: + await asyncio.get_running_loop().run_in_executor( + None, + lambda: ctx.run( + lambda: self._proxy_to_logger(name, event, **kw) + ), + ) + finally: + _ASYNC_CALLING_STACK.reset(scs_token) meth.__name__ = name ameth.__name__ = f"a{name}" @@ -199,17 +218,28 @@ def log(self: Any, level: int, event: str, *args: Any, **kw: Any) -> Any: async def alog( self: Any, level: int, event: str, *args: Any, **kw: Any ) -> Any: + """ + .. versionchanged:: 23.3.0 + Callsite parameters are now also collected under asyncio. + """ if level < min_level: return None name = _LEVEL_TO_NAME[level] if args: event = event % args + scs_token = _ASYNC_CALLING_STACK.set(sys._getframe().f_back) # type: ignore[arg-type] ctx = contextvars.copy_context() - return await asyncio.get_running_loop().run_in_executor( - None, - lambda: ctx.run(lambda: self._proxy_to_logger(name, event, **kw)), - ) + try: + runner = await asyncio.get_running_loop().run_in_executor( + None, + lambda: ctx.run( + lambda: self._proxy_to_logger(name, event, **kw) + ), + ) + finally: + _ASYNC_CALLING_STACK.reset(scs_token) + return runner meths: dict[str, Callable[..., Any]] = {"log": log, "alog": alog} for lvl, name in _LEVEL_TO_NAME.items(): diff --git a/src/structlog/contextvars.py b/src/structlog/contextvars.py index ebb5941d..cc531889 100644 --- a/src/structlog/contextvars.py +++ b/src/structlog/contextvars.py @@ -11,6 +11,8 @@ .. versionchanged:: 21.1.0 Reimplemented without using a single dict as context carrier for improved isolation. Every key-value pair is a separate `contextvars.ContextVar` now. +.. versionchanged:: 23.3.0 + Callsite parameters are now also collected under asyncio. See :doc:`contextvars`. """ @@ -20,6 +22,7 @@ import contextlib import contextvars +from types import FrameType from typing import Any, Generator, Mapping import structlog @@ -30,6 +33,10 @@ STRUCTLOG_KEY_PREFIX = "structlog_" STRUCTLOG_KEY_PREFIX_LEN = len(STRUCTLOG_KEY_PREFIX) +_ASYNC_CALLING_STACK: contextvars.ContextVar[ + FrameType +] = contextvars.ContextVar("_ASYNC_CALLING_STACK") + # For proper isolation, we have to use a dict of ContextVars instead of a # single ContextVar with a dict. # See https://github.com/hynek/structlog/pull/302 for details. diff --git a/src/structlog/processors.py b/src/structlog/processors.py index 7b2377a7..7afc7caa 100644 --- a/src/structlog/processors.py +++ b/src/structlog/processors.py @@ -20,6 +20,7 @@ import threading import time +from types import FrameType from typing import ( Any, Callable, @@ -734,10 +735,6 @@ class CallsiteParameterAdder: dictionaries with information such as the function name, line number and filename that an event dictionary originated from. - .. warning:: - This processor cannot detect the correct callsite for invocation of - async functions. - If the event dictionary has an embedded `logging.LogRecord` object and did not originate from *structlog* then the callsite information will be determined from the `logging.LogRecord` object. For event dictionaries @@ -913,3 +910,60 @@ def __call__( event_dict["event"] = replace_by return event_dict + + +class AddCallingClassPath: + """ + Attempt to identify and add the caller class path to the event dict + under the ``class_path`` key. + + Arguments: + + levels: + A set of log levels to add the ``class_path`` key and + information to. An empty set == * + + .. versionadded:: 23.4.0 + """ + + def __init__(self, levels: set[str] | list[str] | None = None): + self.levels = levels + + def __call__( + self, logger: WrappedLogger, name: str, event_dict: EventDict + ) -> EventDict: + if self.levels and name not in self.levels: + return event_dict + + f, _ = _find_first_app_frame_and_name() + event_dict["class_path"] = self.get_qual_name(f) + + return event_dict + + def get_qual_name(self, frame: FrameType) -> str: + """ + For a given app frame, attempt to deduce the class path + by crawling through the frame's ``f_globals`` to find matching object code. + + This O(n) procedure should return as O(1) in most situations, + but buyer beware. + + Arguments: + + frame: + Frame to process. + + Returns: + + string of the deduced class path + + .. versionadded:: 23.4.0 + """ + for cls in ( + obj for obj in frame.f_globals.values() if inspect.isclass(obj) + ): + member = getattr(cls, frame.f_code.co_name, None) + if inspect.isfunction(member) and member.__code__ == frame.f_code: + return f"{member.__module__}.{member.__qualname__}" + + return f"__main__.{frame.f_code.co_name}" diff --git a/src/structlog/stdlib.py b/src/structlog/stdlib.py index 9de32fd9..0cac0354 100644 --- a/src/structlog/stdlib.py +++ b/src/structlog/stdlib.py @@ -24,7 +24,7 @@ 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 merge_contextvars +from .contextvars import _ASYNC_CALLING_STACK, merge_contextvars from .exceptions import DropEvent from .processors import StackInfoRenderer from .typing import Context, EventDict, ExcInfo, Processor, WrappedLogger @@ -587,13 +587,19 @@ async def _dispatch_to_sync( ) -> None: """ Merge contextvars and log using the sync logger in a thread pool. + .. versionchanged:: 23.3.0 + Callsite parameters are now also collected under asyncio. """ + scs_token = _ASYNC_CALLING_STACK.set(sys._getframe().f_back.f_back) # type: ignore[union-attr, arg-type, unused-ignore] ctx = contextvars.copy_context() - await asyncio.get_running_loop().run_in_executor( - self._executor, - lambda: ctx.run(lambda: meth(event, *args, **kw)), - ) + 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 def debug(self, event: str, *args: Any, **kw: Any) -> None: await self._dispatch_to_sync(self.sync_bl.debug, event, args, kw) diff --git a/tests/test_processors.py b/tests/test_processors.py index c8628302..c990ca38 100644 --- a/tests/test_processors.py +++ b/tests/test_processors.py @@ -27,6 +27,7 @@ from structlog import BoundLogger from structlog._utils import get_processname from structlog.processors import ( + AddCallingClassPath, CallsiteParameter, CallsiteParameterAdder, EventRenamer, @@ -823,12 +824,6 @@ def test_all_parameters(self) -> None: } assert self.parameter_strings == self.get_callsite_parameters().keys() - @pytest.mark.xfail( - reason=( - "CallsiteParameterAdder cannot " - "determine the callsite for async calls." - ) - ) @pytest.mark.asyncio() async def test_async(self) -> None: """ @@ -852,10 +847,14 @@ def __init__(self): callsite_params = self.get_callsite_parameters() await logger.info("baz") + logger_params = json.loads(string_io.getvalue()) - assert {"event": "baz", **callsite_params} == json.loads( - string_io.getvalue() - ) + # These are different when running under async + for key in ["thread", "thread_name"]: + callsite_params.pop(key) + logger_params.pop(key) + + assert {"event": "baz", **callsite_params} == logger_params def test_additional_ignores(self, monkeypatch: pytest.MonkeyPatch) -> None: """ @@ -1173,3 +1172,73 @@ def test_replace_by_key_is_optional(self): assert {"msg": "hi", "foo": "bar"} == EventRenamer("msg", "missing")( None, None, {"event": "hi", "foo": "bar"} ) + + +class TestAddCallingClassPath: + def test_simple_lookup(self): + """ + Simple verification of path interogation + """ + assert "{}.{}.{}".format( + self.__module__, + self.__class__.__qualname__, + sys._getframe().f_code.co_name, + ) == AddCallingClassPath().get_qual_name(sys._getframe()) + + async def test_async_lookup(self): + """ + Simple verification of path interogation against async function + """ + assert "{}.{}.{}".format( + self.__module__, + self.__class__.__qualname__, + sys._getframe().f_code.co_name, + ) == AddCallingClassPath().get_qual_name(sys._getframe()) + + def test_processor(self): + """ + Ensure `AddCallingClassPath` Processor can be enabled, and + that the ``class_path`` details are present and correct in a + log entry + """ + cf = structlog.testing.CapturingLoggerFactory() + structlog.configure( + logger_factory=cf, + processors=[ + structlog.processors.AddCallingClassPath(), + structlog.processors.JSONRenderer(), + ], + ) + structlog.get_logger().info("test!") + assert ( + "{}.{}.{}".format( + self.__module__, + self.__class__.__qualname__, + sys._getframe().f_code.co_name, + ) + == json.loads(cf.logger.calls.pop().args[0])["class_path"] + ) + + async def test_async_processor(self): + """ + Ensure `AddCallingClassPath` Processor can be enabled, and + that the ``class_path`` details are present and correct + in an async log entry + """ + cf = structlog.testing.CapturingLoggerFactory() + structlog.configure( + logger_factory=cf, + processors=[ + structlog.processors.AddCallingClassPath(), + structlog.processors.JSONRenderer(), + ], + ) + await structlog.get_logger().ainfo("test!") + assert ( + "{}.{}.{}".format( + self.__module__, + self.__class__.__qualname__, + sys._getframe().f_code.co_name, + ) + == json.loads(cf.logger.calls.pop().args[0])["class_path"] + )