diff --git a/src/structlog/_frames.py b/src/structlog/_frames.py index fa2292de..76688210 100644 --- a/src/structlog/_frames.py +++ b/src/structlog/_frames.py @@ -9,6 +9,7 @@ from io import StringIO from types import FrameType from typing import List, Optional, Tuple +import inspect from .types import ExcInfo @@ -44,12 +45,16 @@ def _find_first_app_frame_and_name( ignores = ["structlog"] + (additional_ignores or []) f = sys._getframe() name = f.f_globals.get("__name__") or "?" + # sys.stderr.write(f"name={name}\n") while any(tuple(name.startswith(i) for i in ignores)): + # sys.stderr.write(f"name={name}\n") if f.f_back is None: name = "?" break f = f.f_back name = f.f_globals.get("__name__") or "?" + # sys.stderr.write(f"f = {f}, name={name}\n") + # traceback.print_stack() return f, name diff --git a/src/structlog/processors.py b/src/structlog/processors.py index 629203df..db9adaa6 100644 --- a/src/structlog/processors.py +++ b/src/structlog/processors.py @@ -575,11 +575,22 @@ class CallsiteParameterAdder: The keys used for various callsite parameters in the event dictionary are the string values of `CallsiteParameter` members. - :param parameters: A collection of `CallsiteParameter` values that should be added to the event dictionary. + :param parameters: A collection of `CallsiteParameter` values that should be + added to the event dictionary. :param additional_ignores: Additional names with which the first frame must not start. + .. warning:: This processor should not be used in the processor parameter of + a `structlog.stdlib.ProcessorFormatter`, as this will result in the + processor running multiple times for the same event dictionary and + adding invalid values. + + Instead, this function should be used in the ``foreign_pre_chain`` + parameter of `structlog.stdlib.ProcessorFormatter` and in the processors + parameter of `structlog.configure`. + + .. versionadded:: 21.5.0 """ @@ -635,16 +646,31 @@ def __init__( def __call__( self, logger: logging.Logger, name: str, event_dict: EventDict ) -> EventDict: + sys.stderr.write( + f"CallsiteParameterAdder.__call__: event_dict = {event_dict}\n" + ) + import traceback + + traceback.print_stack() record: Optional[logging.LogRecord] = event_dict.get("_record") + if record is not None: - for parameter in self._parameters: - event_dict[parameter.value] = record.__dict__[parameter.value] + from_structlog: Optional[bool] = event_dict.get("_from_structlog") + if not from_structlog: + for parameter in self._parameters: + event_dict[parameter.value] = record.__dict__[ + parameter.value + ] else: frame, module = _find_first_app_frame_and_name( additional_ignores=self._additional_ignores ) + # sys.stderr.write("_find_first_app_frame_and_name: frame = {}\n".format(frame)) + # sys.stderr.write("_find_first_app_frame_and_name: module = {}\n".format(module)) frame_info = inspect.getframeinfo(frame) + # sys.stderr.write("frame_info = {}\n".format(frame_info)) for parameter, handler in self._active_handlers: handler(module, frame_info) event_dict[parameter.value] = handler(module, frame_info) + sys.stderr.write("event_dict = {}\n".format(event_dict)) return event_dict diff --git a/tests/test_processors.py b/tests/test_processors.py index 0437eedb..3602282c 100644 --- a/tests/test_processors.py +++ b/tests/test_processors.py @@ -5,6 +5,7 @@ import datetime import inspect +import itertools import json import logging import os @@ -22,10 +23,11 @@ import structlog from structlog import BoundLogger +from structlog._utils import get_processname from structlog.processors import ( - CallsiteParameterAdder, - CallsiteParameter, CALLSITE_PARAMETERS, + CallsiteParameter, + CallsiteParameterAdder, ExceptionPrettyPrinter, JSONRenderer, KeyValueRenderer, @@ -40,7 +42,7 @@ ) from structlog.stdlib import ProcessorFormatter from structlog.threadlocal import wrap_dict -from structlog._utils import get_processname + try: import simplejson @@ -741,153 +743,200 @@ class TestCallsiteInfoAdder: "processName", } - @pytest.mark.parametrize( - "parameter_strings", - [ - None, - *[{parameter} for parameter in parameter_strings], - set(), - parameter_strings, - {"pathname", "filename"}, - {"module", "funcName"}, - ], - ) - def test_logging_log( - self, - parameter_strings: Optional[Set[str]], - ) -> None: - """ - Callsite parameters are added for event dictionaries that originate from - """ + def test_all_parameters_tested(self) -> None: + assert self.parameter_strings == { + member.value for member in CALLSITE_PARAMETERS + } + + @classmethod + def make_processors(cls, parameter_strings: Optional[Set[str]]) -> None: processors = [] - logging.info("parameter_strings = %s", parameter_strings) if parameter_strings is None: processors.append(CallsiteParameterAdder()) - parameter_strings = self.parameter_strings else: - parameters = self.filter_parameters(parameter_strings) - logging.info("parameters = %s", parameters) + parameters = cls.filter_parameters(parameter_strings) processors.append(CallsiteParameterAdder(parameters=parameters)) - - logger = logging.Logger(sys._getframe().f_code.co_name) - string_io = StringIO() - handler = logging.StreamHandler(string_io) - formatter = ProcessorFormatter( - processors=[*processors, JSONRenderer()], - ) - handler.setFormatter(formatter) - handler.setLevel(0) - logger.addHandler(handler) - logger.setLevel(0) - callsite_params = self.get_callsite_parameters() - logger.info("test message") - - callsite_params = self.filter_parameter_dict( - callsite_params, parameter_strings - ) - out = json.loads(string_io.getvalue()) - assert isinstance(out, dict) - out_item_set = set(out.items()) - expected_item_set = set( - { - "event": "test message", - **callsite_params, - }.items() - ) - assert expected_item_set.issubset(out_item_set), ( - f"{out_item_set}" - "\nshould be a superset of\n" - f"{expected_item_set}" - "\nbut it is missing\n" - f"{expected_item_set.difference(out_item_set)}" - ) - unexpected_params = self.invert_parameter_strings(parameter_strings) - assert unexpected_params.isdisjoint(out.keys()), ( - f"{unexpected_params}" - "\nshould be disjoint with\n" - f"{out.keys()}" - "\nbut contains\n" - f"{unexpected_params.intersection(out.keys())}" - ) + return processors + + # @pytest.mark.parametrize( + # "parameter_strings", + # [ + # None, + # *[{parameter} for parameter in parameter_strings], + # set(), + # parameter_strings, + # {"pathname", "filename"}, + # {"module", "funcName"}, + # ], + # ) + # def test_logging_log( + # self, + # parameter_strings: Optional[Set[str]], + # ) -> None: + # """ + # Callsite parameters are added for event dictionaries that originate from + # """ + # processors = self.make_processors(parameter_strings) + # logger = logging.Logger(sys._getframe().f_code.co_name) + # string_io = StringIO() + # handler = logging.StreamHandler(string_io) + + # formatter = ProcessorFormatter( + # processors=[*processors, JSONRenderer()], + # ) + # handler.setFormatter(formatter) + # handler.setLevel(0) + # logger.addHandler(handler) + # logger.setLevel(0) + + # test_message = "test message" + # callsite_params = self.get_callsite_parameters() + # logger.info(test_message) + + # callsite_params = self.filter_parameter_dict( + # callsite_params, parameter_strings + # ) + # actual = { + # key: value + # for key, value in json.loads(string_io.getvalue()).items() + # if not key.startswith("_") + # } + # expected = { + # "event": test_message, + # **callsite_params, + # } + # assert expected == actual + + # @pytest.mark.parametrize( + # "parameter_strings", + # [ + # None, + # *[{parameter} for parameter in parameter_strings], + # set(), + # parameter_strings, + # {"pathname", "filename"}, + # {"module", "funcName"}, + # ], + # ) + # def test_structlog_log( + # self, + # parameter_strings: Optional[Set[str]], + # ) -> None: + # processors = self.make_processors(parameter_strings) + + # logger = logging.Logger(sys._getframe().f_code.co_name) + # string_io = StringIO() + # handler = logging.StreamHandler(string_io) + # formatter = ProcessorFormatter( + # processors=[JSONRenderer()], + # ) + # handler.setFormatter(formatter) + # handler.setLevel(0) + # logger.addHandler(handler) + # logger.setLevel(0) + + # ctx: Dict[str, Any] = {} + # bound_logger = BoundLogger( + # logger, [*processors, ProcessorFormatter.wrap_for_formatter], ctx + # ) + + # test_message = "test message" + # callsite_params = self.get_callsite_parameters() + # bound_logger.info(test_message) + + # callsite_params = self.filter_parameter_dict( + # callsite_params, parameter_strings + # ) + # actual = { + # key: value + # for key, value in json.loads(string_io.getvalue()).items() + # if not key.startswith("_") + # } + # expected = { + # "event": test_message, + # **callsite_params, + # } + # assert expected == actual @pytest.mark.parametrize( - "parameter_strings", - [ - None, - *[{parameter} for parameter in parameter_strings], - set(), - parameter_strings, - {"pathname", "filename"}, - {"module", "funcName"}, - ], + "setup, front, parameter_strings", + itertools.product( + ["shared", "pre-with-common"], + ["logging", "structlog"], + [ + None, + *[{parameter} for parameter in parameter_strings], + set(), + parameter_strings, + {"pathname", "filename"}, + {"module", "funcName"}, + ], + ), ) - def test_structlog_log( + def test_log( self, + setup: str, + front: str, parameter_strings: Optional[Set[str]], ) -> None: - processors = [] - logging.info("parameter_strings = %s", parameter_strings) - if parameter_strings is None: - processors.append(CallsiteParameterAdder()) - parameter_strings = self.parameter_strings - else: - parameters = self.filter_parameters(parameter_strings) - logging.info("parameters = %s", parameters) - processors.append(CallsiteParameterAdder(parameters=parameters)) - logger = logging.Logger(sys._getframe().f_code.co_name) string_io = StringIO() handler = logging.StreamHandler(string_io) - formatter = ProcessorFormatter( - processors=[JSONRenderer()], - ) + processors = self.make_processors(parameter_strings) + if setup == "shared": + formatter = ProcessorFormatter( + processors=[*processors, JSONRenderer()] + ) + elif setup == "pre-with-common": + formatter = ProcessorFormatter( + foreign_pre_chain=processors, + processors=[JSONRenderer()], + ) + else: + raise ValueError(f"invalid setup {setup}") handler.setFormatter(formatter) handler.setLevel(0) logger.addHandler(handler) logger.setLevel(0) - ctx: Dict[str, Any] = {} - bound_logger = BoundLogger( - logger, [*processors, ProcessorFormatter.wrap_for_formatter], ctx - ) - callsite_params = self.get_callsite_parameters() - bound_logger.info("test message") + + test_message = "test message" + if front == "logging": + callsite_params = self.get_callsite_parameters() + logger.info(test_message) + elif front == "structlog": + ctx: Dict[str, Any] = {} + bound_logger = BoundLogger( + logger, + [*processors, ProcessorFormatter.wrap_for_formatter], + ctx, + ) + callsite_params = self.get_callsite_parameters() + bound_logger.info(test_message) + else: + raise ValueError(f"invalid front {front}") callsite_params = self.filter_parameter_dict( callsite_params, parameter_strings ) - out = json.loads(string_io.getvalue()) - assert isinstance(out, dict) - out_item_set = set(out.items()) - expected_item_set = set( - { - "event": "test message", - **callsite_params, - }.items() - ) - assert expected_item_set.issubset(out_item_set), ( - f"{out_item_set}" - "\nshould be a superset of\n" - f"{expected_item_set}" - "\nbut it is missing\n" - f"{expected_item_set.difference(out_item_set)}" - ) - unexpected_params = self.invert_parameter_strings(parameter_strings) - assert unexpected_params.isdisjoint(out.keys()), ( - f"{unexpected_params}" - "\nshould be disjoint with\n" - f"{out.keys()}" - "\nbut contains\n" - f"{unexpected_params.intersection(out.keys())}" - ) - - @classmethod - def invert_parameter_strings(cls, parameter_strings: Set[str]) -> Set[str]: - return cls.parameter_strings.difference(parameter_strings) + actual = { + key: value + for key, value in json.loads(string_io.getvalue()).items() + if not key.startswith("_") + } + sys.stderr.write(f"actual={actual}\n") + expected = { + "event": test_message, + **callsite_params, + } + sys.stderr.write(f"expected={expected}\n") + assert expected == actual @classmethod def filter_parameters( - cls, parameter_strings: Set[str] + cls, parameter_strings: Optional[Set[str]] ) -> Set[CallsiteParameter]: + if parameter_strings is None: + parameter_strings = cls.parameter_strings return { parameter for parameter in CALLSITE_PARAMETERS @@ -896,8 +945,10 @@ def filter_parameters( @classmethod def filter_parameter_dict( - cls, input: Dict[str, Any], parameter_strings: Set[str] + cls, input: Dict[str, Any], parameter_strings: Optional[Set[str]] ) -> Dict[str, Any]: + if parameter_strings is None: + parameter_strings = cls.parameter_strings return { key: value for key, value in input.items() diff --git a/tests/test_utils.py b/tests/test_utils.py index 9ab10be9..4c471f2b 100644 --- a/tests/test_utils.py +++ b/tests/test_utils.py @@ -4,13 +4,14 @@ # repository for complete details. import errno +import multiprocessing +import sys import pytest from pretend import raiser -from structlog._utils import until_not_interrupted, get_processname -import multiprocessing +from structlog._utils import get_processname, until_not_interrupted class TestUntilNotInterrupted: @@ -40,9 +41,17 @@ def raise_on_first_three(): class TestProcessname: def test_default(self): + """ + The returned process name matches the name of the current process from + the `multiprocessing` module. + """ assert get_processname() == multiprocessing.current_process().name def test_changed(self, monkeypatch: pytest.MonkeyPatch): + """ + The returned process name matches the name of the current process from + the `multiprocessing` module if it is not the default. + """ tmp_name = "fakename" monkeypatch.setattr( target=multiprocessing.current_process(), @@ -50,3 +59,37 @@ def test_changed(self, monkeypatch: pytest.MonkeyPatch): value=tmp_name, ) assert get_processname() == tmp_name + + def test_no_multiprocessing(self, monkeypatch: pytest.MonkeyPatch) -> None: + """ + The returned process name is the default process name the + `multiprocessing` module is not available. + """ + tmp_name = "fakename" + monkeypatch.setattr( + target=multiprocessing.current_process(), + name="name", + value=tmp_name, + ) + monkeypatch.setattr( + target=sys, + name="modules", + value={}, + ) + assert get_processname() == "MainProcess" + + def test_exception(self, monkeypatch: pytest.MonkeyPatch) -> None: + """ + The returned process name is the default process name when an exception + is thrown when an attempt is made to retrive the current process name + from the `multiprocessing` module. + """ + def _current_process() -> None: + raise RuntimeError("test") + + monkeypatch.setattr( + target=multiprocessing, + name="current_process", + value=_current_process, + ) + assert get_processname() == "MainProcess"