From 38aa0f639116176ff3e66d0ed1ed27bff9aa12ba Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Fri, 6 Sep 2024 15:36:08 -0400 Subject: [PATCH 01/29] Small fixes for CI and a license --- .github/workflows/matchers/ruff.json | 14 ++++++++++++++ .github/workflows/ruff.yaml | 9 +++++++-- LICENSE.txt | 21 +++++++++++++++++++++ 3 files changed, 42 insertions(+), 2 deletions(-) create mode 100644 .github/workflows/matchers/ruff.json create mode 100644 LICENSE.txt diff --git a/.github/workflows/matchers/ruff.json b/.github/workflows/matchers/ruff.json new file mode 100644 index 0000000..a9a5917 --- /dev/null +++ b/.github/workflows/matchers/ruff.json @@ -0,0 +1,14 @@ +{ + "problemMatcher": [ + { + "owner": "ruff", + "pattern": [ + { + "regexp": "^(Would reformat): (.+)$", + "message": 1, + "file": 2 + } + ] + } + ] +} diff --git a/.github/workflows/ruff.yaml b/.github/workflows/ruff.yaml index 54d3a36..2d61d70 100644 --- a/.github/workflows/ruff.yaml +++ b/.github/workflows/ruff.yaml @@ -17,6 +17,11 @@ jobs: run: | python -m pip install hatch hatch env create dev - - name: Lint with Ruff + - name: Lint with Ruff (check) run: | - hatch run dev:ruff --output-format=github . + hatch run dev:ruff check --output-format=github . + - name: Register problem matcher for ruff format + run: echo "::add-matcher::.github/workflows/matchers/ruff.json" + - name: Lint with Ruff (format) + run: | + hatch run dev:ruff format --check . diff --git a/LICENSE.txt b/LICENSE.txt new file mode 100644 index 0000000..28a50fa --- /dev/null +++ b/LICENSE.txt @@ -0,0 +1,21 @@ +MIT License + +Copyright GitHub, Inc. + +Permission is hereby granted, free of charge, to any person obtaining a copy +of this software and associated documentation files (the "Software"), to deal +in the Software without restriction, including without limitation the rights +to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +copies of the Software, and to permit persons to whom the Software is +furnished to do so, subject to the following conditions: + +The above copyright notice and this permission notice shall be included in all +copies or substantial portions of the Software. + +THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE +SOFTWARE. From 7f6d8ae0c54eac457f43db227e7f07fe20bdabcb Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Mon, 23 Sep 2024 16:17:55 -0400 Subject: [PATCH 02/29] Split coverage action into two --- .github/workflows/coverage.yaml | 35 +++++++++++++++++++++++++++++++++ .github/workflows/pytest.yaml | 35 +++++++-------------------------- annotated_logger/__init__.py | 4 +++- annotated_logger/mocks.py | 3 ++- example/calculator.py | 9 +++++---- notes.md | 10 ++++++++++ test/test_decorator.py | 10 +++++----- 7 files changed, 67 insertions(+), 39 deletions(-) create mode 100644 .github/workflows/coverage.yaml create mode 100644 notes.md diff --git a/.github/workflows/coverage.yaml b/.github/workflows/coverage.yaml new file mode 100644 index 0000000..7877d8d --- /dev/null +++ b/.github/workflows/coverage.yaml @@ -0,0 +1,35 @@ + +name: Post Coverage Commit + +on: +workflow_run: + workflows: ["Pytest"] + types: + - completed + +jobs: + coverage: + runs-on: ubuntu-latest + if: github.event.workflow_run.event == "pull_request" && github.event.workflow_run.conclusion == "success" + permissions: + pull-requests: write + contents: write + actions: read + steps: + - uses: actions/checkout@v4 + + - uses: actions/download-artifact@v4 + id: download + with: + pattern: coverage-* + merge-multiple: true + - name: Re-add relative so the action is happy + run: | + echo "[run]" >> .coveragerc + echo "relative_files = true" >> .coveragerc + - name: Python Coverage Comment + uses: py-cov-action/python-coverage-comment-action@v3.24 + with: + GITHUB_TOKEN: ${{ github.token }} + MERGE_COVERAGE_FILES: true + GITHUB_PR_RUN_ID: ${{ github.event.workflow_run.id }} diff --git a/.github/workflows/pytest.yaml b/.github/workflows/pytest.yaml index e9fabfb..f563763 100644 --- a/.github/workflows/pytest.yaml +++ b/.github/workflows/pytest.yaml @@ -10,6 +10,7 @@ jobs: pytest: runs-on: ${{ matrix.os }} + permissions: strategy: matrix: os: [ubuntu-latest, macos-latest, windows-latest] @@ -40,32 +41,10 @@ jobs: hatch run dev:pytest env: COVERAGE_FILE: ".coverage.${{ matrix.os }}.${{ matrix.python-version }}" - - name: Store coverage file - uses: actions/upload-artifact@v4 - with: - name: coverage-${{ matrix.os }}-${{ matrix.python-version }} - path: .coverage.${{ matrix.os }}.${{ matrix.python-version }} + - name: Store Pull Request comment to be posted + uses: actions/upload-artifact@v4 + if: steps.coverage_comment.outputs.COMMENT_FILE_WRITTEN == 'true' + with: + name: python-coverage-comment-action + path: python-coverage-comment-action.txt - coverage: - runs-on: ubuntu-latest - needs: pytest - permissions: - pull-requests: write - contents: write - steps: - - uses: actions/checkout@v4 - - - uses: actions/download-artifact@v4 - id: download - with: - pattern: coverage-* - merge-multiple: true - - name: Re-add relative so the action is happy - run: | - echo "[run]" >> .coveragerc - echo "relative_files = true" >> .coveragerc - - name: Python Coverage Comment - uses: py-cov-action/python-coverage-comment-action@v3.24 - with: - GITHUB_TOKEN: ${{ github.token }} - MERGE_COVERAGE_FILES: true diff --git a/annotated_logger/__init__.py b/annotated_logger/__init__.py index 213bd26..23030f5 100644 --- a/annotated_logger/__init__.py +++ b/annotated_logger/__init__.py @@ -340,6 +340,7 @@ def __init__( # noqa: PLR0913 self.formatter = formatter or JsonFormatter( "%(created)s %(levelname)s %(name)s %(message)s" # pragma: no mutate ) + self.handlers = [handler] handler.setFormatter(self.formatter) self.max_length = max_length @@ -356,7 +357,8 @@ def _generate_logger( f"{self.logger_root_name}.{uuid.uuid4()}" # pragma: no mutate ) - logger.addHandler(handler) + for handler_item in self.handlers: + logger.addHandler(handler_item) annotated_filter = self.generate_filter(function=function, cls=cls) diff --git a/annotated_logger/mocks.py b/annotated_logger/mocks.py index bed9ec1..adc3a25 100644 --- a/annotated_logger/mocks.py +++ b/annotated_logger/mocks.py @@ -244,8 +244,9 @@ def assert_logged( @pytest.fixture() -def annotated_logger_mock(mocker: MagicMock) -> AnnotatedLogMock: +def annotated_logger_mock(mocker: MagicMock, annotated_logger_object: AnnotatedLogger) -> AnnotatedLogMock: """Fixture for a mock of the annotated logger.""" + import pdb;pdb.set_trace() return mocker.patch( "annotated_logger.handler", new_callable=AnnotatedLogMock, diff --git a/example/calculator.py b/example/calculator.py index df0b7c7..4b9997f 100644 --- a/example/calculator.py +++ b/example/calculator.py @@ -19,7 +19,7 @@ def runtime(_record: logging.LogRecord) -> str: return "this function is called every time" -annotated_logger = AnnotatedLogger( +ann_logger = AnnotatedLogger( annotations={ "extra": "new data", "nested_extra": {"nested_key": {"double_nested_key": "value"}}, @@ -32,10 +32,10 @@ def runtime(_record: logging.LogRecord) -> str: RemoverPlugin("taskName"), NestedRemoverPlugin(["double_nested_key"]), ], - name="annotated_logger.example", + name="annotated_logger.calculator", ) -annotate_logs = annotated_logger.annotate_logs +annotate_logs = ann_logger.annotate_logs Number = int | float @@ -90,7 +90,7 @@ def check_prediction_crashed_correctly( "Prediction result", extra={"result": success != prediction} ) - @annotated_logger.annotate_logs( + @ann_logger.annotate_logs( success_info=False, pre_call=check_zero_division, _typing_requested=True, @@ -102,6 +102,7 @@ def divide(self, annotated_logger: AnnotatedAdapter) -> Number: "If you divide by zero you'll create a singularity in the fabric of space-time!", # noqa: E501 extra={"joke": True}, ) + import pdb;pdb.set_trace() try: return self.first / self.second except ZeroDivisionError: diff --git a/notes.md b/notes.md new file mode 100644 index 0000000..d582b6f --- /dev/null +++ b/notes.md @@ -0,0 +1,10 @@ +Should support the ability to configure via a logging config. + +The AnnotatedLogger class would take params that let it build/override parts of the config. + +Need to sort out how we do the mock on the handler then. Have the mock fixture pull in a fixture for what handler to do and then if you don't do that you can override that fixture? How does it work with multiple handlers? + + +The overall goal is to be able to support the case where you want to configure multiple output streams (handlers) with different filters. AKA, output with a different log level that filters/formats for actions notifications at the same time as a normal logger + +Also, move base_attribute support into the plugin base and also store the values we add in the annotated (annotated, action and so on). Then make a function that lets a plugin ask for the bits of a record that were added by the caller or the caller and the annotated_logger. diff --git a/test/test_decorator.py b/test/test_decorator.py index cb9abc8..4aa3042 100644 --- a/test/test_decorator.py +++ b/test/test_decorator.py @@ -4,7 +4,7 @@ import test.demo from annotated_logger.mocks import AnnotatedLogMock from example.api import ApiClient -from example.calculator import BoomError, Calculator, annotated_logger +from example.calculator import BoomError, Calculator, ann_logger from example.default import DefaultExample, var_args_and_kwargs_provided_outer @@ -209,8 +209,8 @@ def test_debug(self, annotated_logger_mock): def test_runtime_not_cached(self, annotated_logger_mock, mocker): runtime_mock = mocker.Mock(name="runtime_not_cached") runtime_mock.side_effect = ["first", "second", "third", "fourth"] - runtime_annotations = annotated_logger.runtime_annotations - annotated_logger.runtime_annotations = {"runtime": runtime_mock} + runtime_annotations = ann_logger.runtime_annotations + ann_logger.runtime_annotations = {"runtime": runtime_mock} calc = Calculator(12, 13) calc.subtract() annotated_logger_mock.assert_logged( @@ -231,7 +231,7 @@ def test_runtime_not_cached(self, annotated_logger_mock, mocker): "runtime": "second", }, ) - annotated_logger.runtime_annotations = runtime_annotations + ann_logger.runtime_annotations = runtime_annotations def test_raises_type_error_with_too_few_args(self): calc = Calculator(12, 13) @@ -364,7 +364,7 @@ class Weird: def __len__(self): return 999 - @annotated_logger.annotate_logs(_typing_self=False) + @ann_logger.annotate_logs(_typing_self=False) def test_me(): return Weird() From d3891029a9a9033b722bd1f1052ac28664b7ca5d Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Thu, 26 Sep 2024 18:23:47 -0400 Subject: [PATCH 03/29] Mega commit with ci fixes, and converting to use logging dict --- .github/workflows/coverage.yaml | 12 +- .github/workflows/pytest.yaml | 13 +-- .pre-commit-config.yaml | 2 +- annotated_logger/__init__.py | 191 +++++++++++++++++++++++++------ annotated_logger/mocks.py | 29 ++--- annotated_logger/plugins.py | 15 ++- example/calculator.py | 7 +- example/default.py | 4 - example/logging_config.py | 197 ++++++++++++++++++++++++-------- pyproject.toml | 6 +- test/test_decorator.py | 18 ++- test/test_logging_config.py | 80 +++++++------ test/test_plugins.py | 47 +++++++- 13 files changed, 450 insertions(+), 171 deletions(-) diff --git a/.github/workflows/coverage.yaml b/.github/workflows/coverage.yaml index 7877d8d..7b45ac2 100644 --- a/.github/workflows/coverage.yaml +++ b/.github/workflows/coverage.yaml @@ -1,11 +1,11 @@ name: Post Coverage Commit -on: -workflow_run: - workflows: ["Pytest"] - types: - - completed +on: + workflow_run: + workflows: ["Pytest"] + types: + - completed jobs: coverage: @@ -28,7 +28,7 @@ jobs: echo "[run]" >> .coveragerc echo "relative_files = true" >> .coveragerc - name: Python Coverage Comment - uses: py-cov-action/python-coverage-comment-action@v3.24 + uses: py-cov-action/python-coverage-comment-action@v3.28 with: GITHUB_TOKEN: ${{ github.token }} MERGE_COVERAGE_FILES: true diff --git a/.github/workflows/pytest.yaml b/.github/workflows/pytest.yaml index f563763..9b2ae97 100644 --- a/.github/workflows/pytest.yaml +++ b/.github/workflows/pytest.yaml @@ -10,7 +10,6 @@ jobs: pytest: runs-on: ${{ matrix.os }} - permissions: strategy: matrix: os: [ubuntu-latest, macos-latest, windows-latest] @@ -42,9 +41,9 @@ jobs: env: COVERAGE_FILE: ".coverage.${{ matrix.os }}.${{ matrix.python-version }}" - name: Store Pull Request comment to be posted - uses: actions/upload-artifact@v4 - if: steps.coverage_comment.outputs.COMMENT_FILE_WRITTEN == 'true' - with: - name: python-coverage-comment-action - path: python-coverage-comment-action.txt - + uses: actions/upload-artifact@v4 + if: steps.coverage_comment.outputs.COMMENT_FILE_WRITTEN == 'true' + with: + name: python-coverage-comment-action + path: python-coverage-comment-action.txt + include-hidden-files: true diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index 98814d2..25cd103 100644 --- a/.pre-commit-config.yaml +++ b/.pre-commit-config.yaml @@ -8,7 +8,7 @@ repos: # Run the formatter. - id: ruff-format - repo: https://github.com/RobertCraigie/pyright-python - rev: v1.1.355 + rev: v1.1.382 hooks: - id: pyright # I don't love having to specify these here, but pre-commit only seems to work diff --git a/annotated_logger/__init__.py b/annotated_logger/__init__.py index 23030f5..22fa188 100644 --- a/annotated_logger/__init__.py +++ b/annotated_logger/__init__.py @@ -3,10 +3,10 @@ import contextlib import inspect import logging -import sys +import logging.config import time import uuid -from copy import copy +from copy import copy, deepcopy from typing import ( TYPE_CHECKING, Any, @@ -22,7 +22,6 @@ ) from makefun import wraps -from pythonjsonlogger.jsonlogger import JsonFormatter from annotated_logger.plugins import BasePlugin @@ -88,7 +87,39 @@ class AnnotatedClass(Protocol[C_co]): Annotations = dict[str, Any] -handler = logging.StreamHandler(sys.stdout) +DEFAULT_LOGGING_CONFIG = { + "version": 1, + "disable_existing_loggers": False, + "filters": { + "annotated_filter": { + "annotated_filter": True, + } + }, + "handlers": { + "annotated_handler": { + "class": "logging.StreamHandler", + "filters": ["annotated_filter"], + "formatter": "annotated_formatter", + }, + }, + "formatters": { + "annotated_formatter": { + "class": "pythonjsonlogger.jsonlogger.JsonFormatter", + # Note that this format string uses `time` and `level` which are + # set by the renamer plugin. Because the handler is using the + # annotated_filter the plugings will be run and the fields will be renamed + "format": "{created} {levelname} {name} {message}", + "style": "{", + }, + }, + "loggers": { + "annotated_logger": { + "level": "DEBUG", + "handlers": ["annotated_handler"], + "propagate": False, + }, + }, +} class AnnotatedIterator(Iterator[T]): @@ -177,7 +208,6 @@ def filter(self, record: logging.LogRecord) -> bool: the log record won't be emitted. """ record.__dict__.update(self._all_annotations(record)) - for plugin in self.plugins: try: result = plugin.filter(record) @@ -306,6 +336,7 @@ def __init__( # noqa: PLR0913 max_length: int | None = None, log_level: int = logging.INFO, name: str = "annotated_logger", + config: dict[str, Any] | Literal[False] | None = None, ) -> None: """Store the settings. @@ -324,6 +355,12 @@ def __init__( # noqa: PLR0913 `AnnotatedLogger` object is created in a project this should be set, otherwise settings like level will be overwritten by the second to execute - default 'annotated_logger' + config: Optional - logging config dictionary to be passed to + logging.config.dictConfig or False. If false dictConfig will not be called. + If not passed the DEFAULT_LOGGING_CONFIG will be used. A special + `annotated_filter` keyword is looked for, if present it will be + replaced with a `()` filter config to generate a filter for this + instance of `AnnotatedLogger`. """ if plugins is None: @@ -337,15 +374,32 @@ def __init__( # noqa: PLR0913 self.runtime_annotations = runtime_annotations or {} self.plugins = [BasePlugin()] self.plugins.extend(plugins) - self.formatter = formatter or JsonFormatter( - "%(created)s %(levelname)s %(name)s %(message)s" # pragma: no mutate - ) - self.handlers = [handler] - handler.setFormatter(self.formatter) + if formatter and config: + msg = "Cannot pass both formatter and config." + raise ValueError(msg) + + if config is None: + config = deepcopy(DEFAULT_LOGGING_CONFIG) + if config: + for config_filter in config["filters"].values(): + if config_filter.get("annotated_filter"): + del config_filter["annotated_filter"] + config_filter["()"] = self.generate_filter + + # If we pass in config=False we don't want to configure. + # This is typically because we have another AnnotatedLogger + # object which did run the config and the dict config had config + # for both. + if config: + logging.config.dictConfig(config) + self.max_length = max_length def _generate_logger( - self, function: Function[S, P, R] | None = None, cls: type | None = None + self, + function: Function[S, P, R] | None = None, + cls: type | None = None, + logger_base_name: str | None = None, ) -> AnnotatedAdapter: """Generate a unique adapter with a unique logger object. @@ -353,13 +407,11 @@ def _generate_logger( The filter stores the annotations inside it, so they will mix if a new filter and logger are not created each time. """ + root_name = logger_base_name or self.logger_root_name logger = logging.getLogger( - f"{self.logger_root_name}.{uuid.uuid4()}" # pragma: no mutate + f"{root_name}.{uuid.uuid4()}" # pragma: no mutate ) - for handler_item in self.handlers: - logger.addHandler(handler_item) - annotated_filter = self.generate_filter(function=function, cls=cls) return AnnotatedAdapter(logger, annotated_filter, self.max_length) @@ -370,19 +422,24 @@ def _action_annotation( return {key: f"{function.__module__}:{function.__qualname__}"} def generate_filter( - self, function: Function[S, P, R] | None = None, cls: type[C_co] | None = None + self, + function: Function[S, P, R] | None = None, + cls: type[C_co] | None = None, + annotations: dict[str, Any] | None = None, ) -> AnnotatedFilter: """Create a AnnotatedFilter with the correct annotations and plugins.""" + annotations_passed = annotations + annotations = annotations or {} if function: - annotations = self._action_annotation(function) + annotations.update(self._action_annotation(function)) class_annotations = {} elif cls: class_annotations = {"class": f"{cls.__module__}:{cls.__qualname__}"} - annotations = {} else: - annotations = {} class_annotations = {} - annotations.update(self.annotations) + if not annotations_passed: + annotations.update(self.annotations) + return AnnotatedFilter( annotations=annotations, class_annotations=class_annotations, @@ -394,56 +451,60 @@ def generate_filter( @overload def annotate_logs( self, + logger_name: str | None = None, *, - _typing_class: Literal[True], success_info: bool = True, # pragma: no mutate - pre_call: PreCall[S, P2] = None, - post_call: PostCall[S, P3] = None, - ) -> Callable[[type[C_co]], type[C_co]]: ... + pre_call: PreCall[S2, P2] = None, + post_call: PostCall[S2, P3] = None, + ) -> NoInjectionSelf[S, P, R]: ... - #### Defaults @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, post_call: PostCall[S2, P3] = None, + _typing_requested: Literal[False], ) -> NoInjectionSelf[S, P, R]: ... @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, post_call: PostCall[S2, P3] = None, - _typing_requested: Literal[False], + provided: Literal[False], ) -> NoInjectionSelf[S, P, R]: ... @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, post_call: PostCall[S2, P3] = None, - provided: Literal[False], + _typing_self: Literal[True], ) -> NoInjectionSelf[S, P, R]: ... @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, post_call: PostCall[S2, P3] = None, - _typing_self: Literal[True], ) -> NoInjectionSelf[S, P, R]: ... @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, @@ -455,6 +516,7 @@ def annotate_logs( @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, @@ -466,6 +528,7 @@ def annotate_logs( @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, @@ -477,6 +540,7 @@ def annotate_logs( @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, @@ -486,10 +550,23 @@ def annotate_logs( provided: Literal[False], ) -> NoInjectionSelf[S, P, R]: ... + #### Class True + @overload + def annotate_logs( + self, + logger_name: str | None = None, + *, + _typing_class: Literal[True], + success_info: bool = True, # pragma: no mutate + pre_call: PreCall[S, P2] = None, + post_call: PostCall[S, P3] = None, + ) -> Callable[[type[C_co]], type[C_co]]: ... + ### Instance False @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, @@ -500,6 +577,7 @@ def annotate_logs( @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, @@ -511,6 +589,7 @@ def annotate_logs( @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, @@ -522,6 +601,7 @@ def annotate_logs( @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, @@ -535,6 +615,7 @@ def annotate_logs( @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, @@ -545,6 +626,7 @@ def annotate_logs( @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, @@ -556,6 +638,7 @@ def annotate_logs( @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, @@ -567,6 +650,7 @@ def annotate_logs( @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, @@ -582,6 +666,7 @@ def annotate_logs( @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, @@ -593,6 +678,7 @@ def annotate_logs( @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, @@ -606,6 +692,7 @@ def annotate_logs( @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, @@ -619,9 +706,11 @@ def annotate_logs( @overload def annotate_logs( self, + logger_name: str | None = None, *, success_info: bool = True, # pragma: no mutate pre_call: PreCall[S2, P2] = None, + post_call: PostCall[S2, P2] = None, _typing_self: Literal[False], _typing_requested: Literal[True], provided: Literal[True], @@ -632,6 +721,7 @@ def annotate_logs( # So, ignoring the complexity metric def annotate_logs( # noqa: C901 self, + logger_name: str | None = None, *, success_info: bool = True, pre_call: PreCall[S2, P2] = None, @@ -645,6 +735,8 @@ def annotate_logs( # noqa: C901 Args: ---- + logger_name: Optional - Specify the name of the logger attached to + the decorated function. success_info: Log success at an info level, if falsey success will be logged at debug. Default: True provided: Boolean that indicates the caller will be providing it's @@ -701,7 +793,9 @@ def decorator( # noqa: C901 def wrap_class( *args: P.args, **kwargs: P.kwargs ) -> AnnotatedClass[C_co]: - logger = self._generate_logger(cls=wrapped) + logger = self._generate_logger( + cls=wrapped, logger_base_name=logger_name + ) logger.debug("init") new = cast(AnnotatedClass[C_co], wrapped(*args, **kwargs)) new.annotated_logger = logger @@ -723,7 +817,7 @@ def wrap_function(*args: P.args, **kwargs: P.kwargs) -> R: post_call_attempted = False # pragma: no mutate new_args, new_kwargs, logger, pre_execution_annotations = inject_logger( - list(args), kwargs + list(args), kwargs, logger_base_name=logger_name ) try: start_time = time.perf_counter() @@ -766,7 +860,10 @@ def wrap_function(*args: P.args, **kwargs: P.kwargs) -> R: return decorator def _determine_signature_adjustments( - self, function: Function[S, P, R], *, provided: bool + self, + function: Function[S, P, R], + *, + provided: bool, ) -> tuple[ list[str], Callable[ @@ -790,10 +887,14 @@ def _determine_signature_adjustments( remove_args = ["annotated_logger"] def inject_logger( - args: list[Any], kwargs: dict[str, Any] + args: list[Any], + kwargs: dict[str, Any], + logger_base_name: str | None = None, ) -> tuple[list[Any], dict[str, Any], AnnotatedAdapter, Annotations | None]: if not logger_requested: - logger = self._generate_logger(function) + logger = self._generate_logger( + function, logger_base_name=logger_base_name + ) return (args, kwargs, logger, None) by_index = False # pragma: no mutate @@ -813,6 +914,7 @@ def inject_logger( args=new_args, index=index, function=function, + logger_base_name=logger_base_name, ) else: logger, annotations, new_kwargs = self._inject_by_kwarg( @@ -820,6 +922,7 @@ def inject_logger( instance_method=instance_method, kwargs=new_kwargs, function=function, + logger_base_name=logger_base_name, ) return new_args, new_kwargs, logger, annotations @@ -833,6 +936,7 @@ def _inject_by_kwarg( instance_method: bool, function: Function[S, P, R], kwargs: dict[str, Any], + logger_base_name: str | None = None, ) -> tuple[AnnotatedAdapter, Annotations | None, dict[str, Any]]: if provided: instance = kwargs["annotated_logger"] @@ -840,13 +944,15 @@ def _inject_by_kwarg( instance = kwargs["self"] else: instance = False # pragma: no mutate - logger, annotations = self._pick_correct_logger(function, instance) + logger, annotations = self._pick_correct_logger( + function, instance, logger_base_name=logger_base_name + ) if not provided: kwargs["annotated_logger"] = logger return logger, annotations, kwargs - def _inject_by_index( + def _inject_by_index( # noqa: PLR0913 self, *, provided: bool, @@ -854,6 +960,7 @@ def _inject_by_index( function: Function[S, P, R], args: list[Any], index: int, + logger_base_name: str | None = None, ) -> tuple[AnnotatedAdapter, Annotations | None, list[Any]]: if provided: instance = args[index] @@ -861,7 +968,9 @@ def _inject_by_index( instance = args[0] else: instance = False # pragma: no mutate - logger, annotations = self._pick_correct_logger(function, instance) + logger, annotations = self._pick_correct_logger( + function, instance, logger_base_name=logger_base_name + ) if not provided: args.insert(index, logger) return logger, annotations, args @@ -881,7 +990,10 @@ def _check_parameters_for_self_and_cls( return index, instance_method def _pick_correct_logger( - self, function: Function[S, P, R], instance: object | bool + self, + function: Function[S, P, R], + instance: object | bool, + logger_base_name: str | None = None, ) -> tuple[AnnotatedAdapter, Annotations | None]: """Use the instance's logger and annotations if present.""" if instance and hasattr(instance, "annotated_logger"): @@ -898,7 +1010,10 @@ def _pick_correct_logger( ) return (logger, annotations) - return (self._generate_logger(function), None) + return ( + self._generate_logger(function, logger_base_name=logger_base_name), + None, + ) def _attempt_post_call( diff --git a/annotated_logger/mocks.py b/annotated_logger/mocks.py index adc3a25..caad756 100644 --- a/annotated_logger/mocks.py +++ b/annotated_logger/mocks.py @@ -1,16 +1,11 @@ from __future__ import annotations import logging -from typing import TYPE_CHECKING, Any, Literal +from typing import Any, Literal import pychoir import pytest -import annotated_logger - -if TYPE_CHECKING: # pragma: no cover - from unittest.mock import MagicMock - class AssertLogged: """Stores the data from a call to `assert_logged` and checks if there is a match.""" @@ -165,7 +160,7 @@ def _check_record_matches( return differences -class AnnotatedLogMock: +class AnnotatedLogMock(logging.Handler): """Mock that captures logs and provides extra assertion logic.""" ALL = "ALL" @@ -244,11 +239,19 @@ def assert_logged( @pytest.fixture() -def annotated_logger_mock(mocker: MagicMock, annotated_logger_object: AnnotatedLogger) -> AnnotatedLogMock: +def annotated_logger_object() -> logging.Logger: + """Logger to wrap with the `annotated_logger_mock` fixture.""" + return logging.getLogger("annotated_logger") + + +@pytest.fixture() +def annotated_logger_mock(annotated_logger_object: logging.Logger) -> AnnotatedLogMock: """Fixture for a mock of the annotated logger.""" - import pdb;pdb.set_trace() - return mocker.patch( - "annotated_logger.handler", - new_callable=AnnotatedLogMock, - handler=annotated_logger.handler, + handler = annotated_logger_object.handlers[0] + annotated_logger_object.removeHandler(handler) + mock_handler = AnnotatedLogMock( + handler=handler, ) + + annotated_logger_object.addHandler(mock_handler) + return mock_handler diff --git a/annotated_logger/plugins.py b/annotated_logger/plugins.py index ac2fa8a..d72b14e 100644 --- a/annotated_logger/plugins.py +++ b/annotated_logger/plugins.py @@ -43,15 +43,22 @@ def uncaught_exception( class RenamerPlugin(BasePlugin): """Plugin that prevents name collisions.""" - def __init__(self, **kwargs: str) -> None: + class FieldNotPresentError(Exception): + """Exception for a field that is supposed to be renamed, but is not present.""" + + def __init__(self, *, strict: bool = False, **kwargs: str) -> None: """Store the list of names to rename and pre/post fixs.""" self.targets = kwargs + self.strict = strict def filter(self, record: logging.LogRecord) -> bool: - """Adjust the name of any fields that match a provided list.""" + """Adjust the name of any fields that match a provided list if they exist.""" for new, old in self.targets.items(): - record.__dict__[new] = record.__dict__[old] - del record.__dict__[old] + if old in record.__dict__: + record.__dict__[new] = record.__dict__[old] + del record.__dict__[old] + elif self.strict: + raise RenamerPlugin.FieldNotPresentError(old) return True diff --git a/example/calculator.py b/example/calculator.py index 4b9997f..f5c9010 100644 --- a/example/calculator.py +++ b/example/calculator.py @@ -19,7 +19,7 @@ def runtime(_record: logging.LogRecord) -> str: return "this function is called every time" -ann_logger = AnnotatedLogger( +annotated_logger = AnnotatedLogger( annotations={ "extra": "new data", "nested_extra": {"nested_key": {"double_nested_key": "value"}}, @@ -35,7 +35,7 @@ def runtime(_record: logging.LogRecord) -> str: name="annotated_logger.calculator", ) -annotate_logs = ann_logger.annotate_logs +annotate_logs = annotated_logger.annotate_logs Number = int | float @@ -90,7 +90,7 @@ def check_prediction_crashed_correctly( "Prediction result", extra={"result": success != prediction} ) - @ann_logger.annotate_logs( + @annotated_logger.annotate_logs( success_info=False, pre_call=check_zero_division, _typing_requested=True, @@ -102,7 +102,6 @@ def divide(self, annotated_logger: AnnotatedAdapter) -> Number: "If you divide by zero you'll create a singularity in the fabric of space-time!", # noqa: E501 extra={"joke": True}, ) - import pdb;pdb.set_trace() try: return self.first / self.second except ZeroDivisionError: diff --git a/example/default.py b/example/default.py index 7fbfb60..5876ee6 100644 --- a/example/default.py +++ b/example/default.py @@ -16,16 +16,12 @@ def foo(self, annotated_logger: AnnotatedAdapter) -> None: """Emit an info log.""" annotated_logger.info("foo") - # def test(self, _first, *args): - # pass - @annotate_logs(_typing_requested=True) def var_args( self, annotated_logger: AnnotatedAdapter, _first: str, *my_args: str, - # self, annotated_logger: AnnotatedAdapter, _first: str, *my_args: str ) -> bool: """Take a splat of args.""" annotated_logger.annotate(first=_first) diff --git a/example/logging_config.py b/example/logging_config.py index f11c19f..a79b4ff 100644 --- a/example/logging_config.py +++ b/example/logging_config.py @@ -1,75 +1,166 @@ import logging import logging.config -from pythonjsonlogger.jsonlogger import JsonFormatter - -from annotated_logger import AnnotatedAdapter, AnnotatedLogger -from annotated_logger.plugins import RenamerPlugin - - -def runtime(_record: logging.LogRecord) -> str: - """Return the string every time.""" - return "this function is called every time" - - -annotated_logger = AnnotatedLogger( - annotations={"extra": "new data"}, - runtime_annotations={"runtime": runtime}, - plugins=[RenamerPlugin(time="created", level="levelname")], - formatter=JsonFormatter("%(time)s %(level)s %(name)s %(message)s"), - log_level=logging.DEBUG, - max_length=200, - name="annotated_logger.logging_config", -) -annotate_logs = annotated_logger.annotate_logs - -weird_annotated_logger = AnnotatedLogger( - annotations={"weird": True}, - plugins=[RenamerPlugin(time="created", lvl="levelname")], - formatter=JsonFormatter("%(time)s %(lvl)s %(name)s %(message)s"), - log_level=logging.DEBUG, - name="annotated_logger.weird_logging_config", -) -weird_annotate_logs = weird_annotated_logger.annotate_logs - -# This is roughly how django configures it's logging. -# Use this as a base (but change `demo` to `django` to apply to all the django logs +from annotated_logger import AnnotatedAdapter, AnnotatedFilter, AnnotatedLogger +from annotated_logger.plugins import BasePlugin, RenamerPlugin + +# This logging config creates 4 loggers: +# * A logger for "annotated_logger.logging_config", which logs all messages as json and +# also logs errors as plain text. This is an example of how to log to multiple places. +# * A logger for "annotated_logger.logging_config_weird", which logs all messages at +# info and up. It has a different namespace (_weird instead of .weird) and so has +# isolated annotations. +# * A logger for "annotated_logger.logging_config.long", which logs all messages at info +# as text with a note added. This logger allows it's logs to propagate up and so the +# "annotated_logger.logging_config" logger will also log these messages in it's json +# format without the note from this logger. +# * A logger for "annotated_logger.logging_config.logger", which logs all messages as +# json. This logger does not propagate so that the "annotated_logger.logging_config" +# logger doesn't also log these messages. This logger is used by a non annotated +# method, but defines a filter that is annotated with the base annotations defined +# in `AnnotatedLogger(...`. This is an example of how to add annotations to external +# logs such as django. Note, the annotations this logger receives are based on the +# annotations passed in to the `AnnotatedLogger` invocation with the config, +# The second invocation for "weird" has different annotations. You should be able +# to have multiple of these with different annotations by invoking `AnnotatedLogger` +# multiple times and including `disable_existing_loggers` in the later configs. +# You can also provide custom annotations here if you wish to override the +# annotations from the annotated logger. +# +# Note: When creating multiple loggers, especially when doing so in different +# files/configs keep in mind that names should be unique or they will override +# eachother leaving you with a very confusing mess. LOGGING = { "version": 1, + "disable_existing_loggers": False, "filters": { - "annotated_filter": { - "()": annotated_logger.generate_filter, - "function": None, - } + "logging_config.logger_filter": { + "annotated_filter": True, + # You can override the annotations that would be provided like so + # But, if you want to do that you are likely better off + # using a filter not associated with an AnnotatedLogger + # like the `logging_config.logger_filter_parens` below + # "annotations": {"decorated": False}, # noqa: ERA001 + }, + "logging_config.logger_filter_parens": { + "()": AnnotatedFilter, + "annotations": {"decorated": False}, + "class_annotations": {}, + "runtime_annotations": {"custom_runtime": lambda _record: True}, + "plugins": [BasePlugin()], + }, }, "handlers": { - "annotated_handler": { + "logging_config.annotated_handler": { + "class": "logging.StreamHandler", + "formatter": "logging_config.annotated_formatter", + }, + "logging_config.logger_handler": { + "class": "logging.StreamHandler", + "filters": [ + "logging_config.logger_filter", + "logging_config.logger_filter_parens", + ], + "formatter": "logging_config.annotated_formatter", + }, + "logging_config.long_handler": { + "class": "logging.StreamHandler", + "formatter": "logging_config.long_formatter", + }, + "logging_config.error_handler": { + "class": "logging.StreamHandler", + "level": "ERROR", + "formatter": "logging_config.error_formatter", + }, + "logging_config.weird_handler": { "class": "logging.StreamHandler", - "filters": ["annotated_filter"], - "formatter": "annotated_formatter", - } + "formatter": "logging_config.weird_formatter", + }, }, "formatters": { - "annotated_formatter": { + "logging_config.annotated_formatter": { "class": "pythonjsonlogger.jsonlogger.JsonFormatter", # Note that this format string uses `time` and `level` which are # set by the renamer plugin. Because the handler is using the # annotated_filter the plugings will be run and the fields will be renamed - "format": "{time} {level} {module} {extra} {runtime} {message}", + # This also pulls the `runtime` annotation to a specific place in the log + "format": "{time} {level} {name} {runtime} {message}", + "style": "{", + }, + "logging_config.error_formatter": { + "format": "{level} {message}", + "style": "{", + }, + "logging_config.long_formatter": { + "format": "{level} Long message, may be split {message}", + # 3.12 added support for defaults in dict configs + # With that we can add the format and defaults below + # for a more realistic example. Not all of the messages + # in the method we set to use this are long enough to be split, + # so, some of them don't have the message_part(s) fields. + # "format": "{level} {message_part}/{message_parts} {message}", # noqa: ERA001 E501 + # "defaults": {"message_part": 1, "message_parts": 1}, # noqa: ERA001 + "style": "{", + }, + "logging_config.weird_formatter": { + "class": "pythonjsonlogger.jsonlogger.JsonFormatter", + "format": "{time} {lvl} {name} {message}", "style": "{", }, }, "loggers": { - "demo": { + "annotated_logger.logging_config": { "level": "DEBUG", - "handlers": ["annotated_handler"], + "handlers": [ + "logging_config.annotated_handler", + "logging_config.error_handler", + ], + "propagate": True, + }, + "annotated_logger.logging_config_weird": { + "level": "INFO", + "handlers": ["logging_config.weird_handler"], + "propagate": True, + }, + "annotated_logger.logging_config.long": { + "level": "INFO", + "handlers": ["logging_config.long_handler"], + "propagate": True, + }, + "annotated_logger.logging_config.logger": { + "handlers": ["logging_config.logger_handler"], + "propagate": False, }, }, } -logging.config.dictConfig(LOGGING) -logger = logging.getLogger("demo") +def runtime(_record: logging.LogRecord) -> str: + """Return the string every time.""" + return "this function is called every time" + + +annotated_logger = AnnotatedLogger( + annotations={"hostname": "my-host"}, + runtime_annotations={"runtime": runtime}, + plugins=[RenamerPlugin(time="created", level="levelname")], + log_level=logging.DEBUG, + max_length=200, + name="annotated_logger.logging_config", + config=LOGGING, +) +annotate_logs = annotated_logger.annotate_logs + +weird_annotated_logger = AnnotatedLogger( + annotations={"weird": True}, + plugins=[RenamerPlugin(time="created", lvl="levelname")], + log_level=logging.INFO, + name="annotated_logger.logging_config_weird", + config=False, +) +weird_annotate_logs = weird_annotated_logger.annotate_logs + +logger = logging.getLogger("annotated_logger.logging_config.logger") logger.setLevel("DEBUG") @@ -90,7 +181,10 @@ def make_some_annotated_logs(annotated_logger: AnnotatedAdapter) -> None: annotated_logger.error("this is error") -@weird_annotate_logs(_typing_requested=True, _typing_self=False) +@weird_annotate_logs( + _typing_requested=True, + _typing_self=False, +) def make_some_weird_logs(annotated_logger: AnnotatedAdapter) -> None: """Log messages using the provided annotated_logger.""" annotated_logger.debug("this is debug") @@ -99,7 +193,12 @@ def make_some_weird_logs(annotated_logger: AnnotatedAdapter) -> None: annotated_logger.error("this is error") -@annotate_logs(_typing_requested=True, _typing_self=False) +@annotate_logs( + _typing_requested=True, + _typing_self=False, + logger_name="annotated_logger.logging_config.long", + success_info=False, +) def log_really_long_message(annotated_logger: AnnotatedAdapter) -> None: """Log a message that is so long it will get split.""" message = "1" * 200 + "2" * 200 + "3333" diff --git a/pyproject.toml b/pyproject.toml index 14e22de..e28bc91 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -6,7 +6,7 @@ build-backend = "hatchling.build" name = "annotated-logger" dynamic = ["version"] description = "A decorator that logs the start and end of a function as well as providing an optional logger with annotations" -readme = "README.md" +readme = "REadme.md" license = "" requires-python = ">=3.6" authors = [ @@ -93,7 +93,9 @@ reportMissingTypeArgument = true # -p no:annotated_logger disables the plugin so that we can request it conftest.py # get coverage correctly, users will not have to do this. # See https://github.com/pytest-dev/pytest/issues/935 -addopts = "--cov=annotated_logger --cov=example --cov-report html --cov-report term -p no:annotated_logger" +# --forked will run each test in it's own process, which prevents the logging configs +# from overriding eachother and clobbering the handlers and the like +addopts = "--cov=annotated_logger --cov=example --cov-report html --cov-report term -p no:annotated_logger --forked" filterwarnings = [ "error", ] diff --git a/test/test_decorator.py b/test/test_decorator.py index 4aa3042..2b79649 100644 --- a/test/test_decorator.py +++ b/test/test_decorator.py @@ -1,10 +1,13 @@ +import logging + import pytest from pychoir.strings import StartsWith import test.demo +from annotated_logger import AnnotatedLogger from annotated_logger.mocks import AnnotatedLogMock from example.api import ApiClient -from example.calculator import BoomError, Calculator, ann_logger +from example.calculator import BoomError, Calculator, annotated_logger from example.default import DefaultExample, var_args_and_kwargs_provided_outer @@ -209,8 +212,8 @@ def test_debug(self, annotated_logger_mock): def test_runtime_not_cached(self, annotated_logger_mock, mocker): runtime_mock = mocker.Mock(name="runtime_not_cached") runtime_mock.side_effect = ["first", "second", "third", "fourth"] - runtime_annotations = ann_logger.runtime_annotations - ann_logger.runtime_annotations = {"runtime": runtime_mock} + runtime_annotations = annotated_logger.runtime_annotations + annotated_logger.runtime_annotations = {"runtime": runtime_mock} calc = Calculator(12, 13) calc.subtract() annotated_logger_mock.assert_logged( @@ -231,7 +234,7 @@ def test_runtime_not_cached(self, annotated_logger_mock, mocker): "runtime": "second", }, ) - ann_logger.runtime_annotations = runtime_annotations + annotated_logger.runtime_annotations = runtime_annotations def test_raises_type_error_with_too_few_args(self): calc = Calculator(12, 13) @@ -364,7 +367,7 @@ class Weird: def __len__(self): return 999 - @ann_logger.annotate_logs(_typing_self=False) + @annotated_logger.annotate_logs(_typing_self=False) def test_me(): return Weird() @@ -595,3 +598,8 @@ def test_annotated_logger_must_be_first(self): TypeError, match="^annotated_logger must be the first argument$" ): import example.invalid_order # noqa: F401 + + def test_cannot_use_both_formatter_and_config(self): + formatter = logging.Formatter("%(time)s %(lvl)s %(name)s %(message)s") + with pytest.raises(ValueError, match="Cannot pass both formatter and config."): + AnnotatedLogger(formatter=formatter, config={"logging": "config"}) diff --git a/test/test_logging_config.py b/test/test_logging_config.py index e7d9bfe..abaa8fc 100644 --- a/test/test_logging_config.py +++ b/test/test_logging_config.py @@ -1,32 +1,30 @@ +import logging + +import pytest + import example.logging_config from annotated_logger.mocks import AnnotatedLogMock +@pytest.fixture() +def annotated_logger_object(): + return logging.getLogger("annotated_logger.logging_config") + + class TestLoggingConfig: - def test_base_logging(self, caplog): + @pytest.mark.parametrize( + "annotated_logger_object", + [logging.getLogger("annotated_logger.logging_config.logger")], + ) + def test_base_logging(self, annotated_logger_mock): example.logging_config.make_some_logs() - for i, level in enumerate(["debug", "info", "warning", "error"]): - log = { - "annotated": True, - "args": (), - "exc_info": None, - "exc_text": None, - "extra": "new data", - "filename": "logging_config.py", - "funcName": "make_some_logs", - "level": level.upper(), - "levelno": (i + 1) * 10, - "message": f"this is {level}", - "module": "logging_config", - "msg": f"this is {level}", - "name": "demo", - "processName": "MainProcess", - "runtime": "this function is called every time", - "stack_info": None, - "threadName": "MainThread", - } - for k, v in log.items(): - assert v == caplog.records[i].__dict__[k] + for level in ["debug", "info", "warning", "error"]: + annotated_logger_mock.assert_logged( + level, + f"this is {level}", + present={"hostname": "my-host"}, + absent=["weird"], + ) def test_annotated_logging(self, annotated_logger_mock: AnnotatedLogMock): example.logging_config.make_some_annotated_logs() @@ -34,7 +32,7 @@ def test_annotated_logging(self, annotated_logger_mock: AnnotatedLogMock): "DEBUG", "start", present={ - "extra": "new data", + "hostname": "my-host", "annotated": True, "runtime": "this function is called every time", }, @@ -43,12 +41,16 @@ def test_annotated_logging(self, annotated_logger_mock: AnnotatedLogMock): "DEBUG", "this is debug", present={ - "extra": "new data", + "hostname": "my-host", "annotated": True, "runtime": "this function is called every time", }, ) + @pytest.mark.parametrize( + "annotated_logger_object", + [logging.getLogger("annotated_logger.logging_config_weird")], + ) def test_weird_logging(self, annotated_logger_mock: AnnotatedLogMock): example.logging_config.make_some_weird_logs() annotated_logger_mock.assert_logged( @@ -58,7 +60,9 @@ def test_weird_logging(self, annotated_logger_mock: AnnotatedLogMock): "weird": True, "annotated": True, }, - absent="extra", + absent="hostname", + # The weird logging level is info + count=0, ) annotated_logger_mock.assert_logged( "INFO", @@ -67,7 +71,7 @@ def test_weird_logging(self, annotated_logger_mock: AnnotatedLogMock): "weird": True, "annotated": True, }, - absent="extra", + absent="hostname", ) annotated_logger_mock.assert_logged( "WARNING", @@ -76,7 +80,7 @@ def test_weird_logging(self, annotated_logger_mock: AnnotatedLogMock): "weird": True, "annotated": True, }, - absent="extra", + absent="hostname", ) annotated_logger_mock.assert_logged( "ERROR", @@ -85,16 +89,20 @@ def test_weird_logging(self, annotated_logger_mock: AnnotatedLogMock): "weird": True, "annotated": True, }, - absent="extra", + absent="hostname", ) + @pytest.mark.parametrize( + "annotated_logger_object", + [logging.getLogger("annotated_logger.logging_config.long")], + ) def test_really_long_message(self, annotated_logger_mock: AnnotatedLogMock): example.logging_config.log_really_long_message() annotated_logger_mock.assert_logged( "INFO", "1" * 200, present={ - "extra": "new data", + "hostname": "my-host", "annotated": True, "runtime": "this function is called every time", "message_part": 1, @@ -107,7 +115,7 @@ def test_really_long_message(self, annotated_logger_mock: AnnotatedLogMock): "INFO", "2" * 200, present={ - "extra": "new data", + "hostname": "my-host", "annotated": True, "runtime": "this function is called every time", "message_part": 2, @@ -120,7 +128,7 @@ def test_really_long_message(self, annotated_logger_mock: AnnotatedLogMock): "INFO", "3333", present={ - "extra": "new data", + "hostname": "my-host", "annotated": True, "runtime": "this function is called every time", "message_part": 3, @@ -133,7 +141,7 @@ def test_really_long_message(self, annotated_logger_mock: AnnotatedLogMock): "INFO", "4" * 200, present={ - "extra": "new data", + "hostname": "my-host", "annotated": True, "runtime": "this function is called every time", }, @@ -143,7 +151,7 @@ def test_really_long_message(self, annotated_logger_mock: AnnotatedLogMock): "INFO", "5" * 200, present={ - "extra": "new data", + "hostname": "my-host", "annotated": True, "runtime": "this function is called every time", "message_part": 1, @@ -156,7 +164,7 @@ def test_really_long_message(self, annotated_logger_mock: AnnotatedLogMock): "INFO", "5", present={ - "extra": "new data", + "hostname": "my-host", "annotated": True, "runtime": "this function is called every time", "message_part": 2, @@ -169,7 +177,7 @@ def test_really_long_message(self, annotated_logger_mock: AnnotatedLogMock): "INFO", "6" * 199, present={ - "extra": "new data", + "hostname": "my-host", "annotated": True, "runtime": "this function is called every time", }, diff --git a/test/test_plugins.py b/test/test_plugins.py index f3a4533..3559fb3 100644 --- a/test/test_plugins.py +++ b/test/test_plugins.py @@ -4,7 +4,7 @@ from requests.exceptions import HTTPError from annotated_logger import AnnotatedAdapter, AnnotatedLogger -from annotated_logger.plugins import BasePlugin +from annotated_logger.plugins import BasePlugin, RenamerPlugin from example.api import ApiClient from example.calculator import Calculator @@ -40,6 +40,11 @@ def filter(self, _record: logging.LogRecord) -> bool: def annotated_logger(plugins): return AnnotatedLogger( plugins=plugins, + name="annotated_logger.test_plugins", + # I believe that allowing this to set config leads to duplicate + # filters/handlers that re-written on each dictConfig call, + # but aren't overwritten, just hidden/dereferences, but still called + config=False, ) @@ -68,6 +73,13 @@ def skip_plugin(): return SpyPlugin(filter_message=True) +# Request the annotated_logger fixture so that the config +# has been setup before we get the logger +@pytest.fixture() +def annotated_logger_object(annotated_logger): # noqa: ARG001 + return logging.getLogger("annotated_logger") + + class TestPlugins: class TestSkip: @pytest.fixture() @@ -90,7 +102,9 @@ class TestWorking: def plugins(self, working_plugin): return [working_plugin] - def test_working_filter(self, annotate_logs, working_plugin): + def test_working_filter( + self, annotated_logger_mock, annotate_logs, working_plugin + ): @annotate_logs() def should_work(): return True @@ -99,6 +113,7 @@ def should_work(): assert working_plugin.filter_called is False should_work() assert working_plugin.filter_called is True + annotated_logger_mock.assert_logged("info", "success") def test_working_exception(self, annotate_logs, working_plugin): @annotate_logs() @@ -177,6 +192,34 @@ def test_joke_should_be_cheezy(self, annotated_logger_mock): absent=["joke"], ) + def test_field_missing_strict(self, annotated_logger_mock): + annotate_logs = AnnotatedLogger( + plugins=[RenamerPlugin(strict=True, made_up_field="some_other_field")], + name="annotated_logger.test_plugins", + config=False, + ).annotate_logs + + wrapped = annotate_logs(_typing_self=False)(lambda: True) + wrapped() + + assert annotated_logger_mock.records[0].failed_plugins == [ + "" + ] + + def test_field_missing_not_strict(self, annotated_logger_mock): + annotate_logs = AnnotatedLogger( + plugins=[RenamerPlugin(strict=False, made_up_field="some_other_field")], + name="annotated_logger.test_plugins", + config=False, + ).annotate_logs + + wrapped = annotate_logs(_typing_self=False)(lambda: True) + wrapped() + + record = annotated_logger_mock.records[0] + with pytest.raises(AttributeError): + _ = record.failed_plugins + class TestNestedRemoverPlugin: def test_exclude_nested_fields(self, annotated_logger_mock): From 0dd17135ace93d83e405b07ba6e566729be1405a Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Fri, 27 Sep 2024 17:14:11 -0400 Subject: [PATCH 04/29] Apparently, it was really mad I had a typo in the readme name --- pyproject.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pyproject.toml b/pyproject.toml index e28bc91..b5458ae 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -6,7 +6,7 @@ build-backend = "hatchling.build" name = "annotated-logger" dynamic = ["version"] description = "A decorator that logs the start and end of a function as well as providing an optional logger with annotations" -readme = "REadme.md" +readme = "Readme.md" license = "" requires-python = ">=3.6" authors = [ From a3fcf2b0f2a78509add2a9f198ad576b25346e47 Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Mon, 7 Oct 2024 15:46:02 -0400 Subject: [PATCH 05/29] Not sure how that got uncapitalized --- pyproject.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pyproject.toml b/pyproject.toml index b5458ae..7e4b45e 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -6,7 +6,7 @@ build-backend = "hatchling.build" name = "annotated-logger" dynamic = ["version"] description = "A decorator that logs the start and end of a function as well as providing an optional logger with annotations" -readme = "Readme.md" +readme = "README.md" license = "" requires-python = ">=3.6" authors = [ From 74814bcffaa6570536ee45e85b0435929f9b3ada Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Mon, 7 Oct 2024 15:46:58 -0400 Subject: [PATCH 06/29] Working on smushing mutations --- annotated_logger/__init__.py | 3 ++- example/logging_config.py | 4 ++-- test/test_decorator.py | 4 +++- test/test_logging_config.py | 2 +- 4 files changed, 8 insertions(+), 5 deletions(-) diff --git a/annotated_logger/__init__.py b/annotated_logger/__init__.py index 22fa188..f42e4dd 100644 --- a/annotated_logger/__init__.py +++ b/annotated_logger/__init__.py @@ -87,7 +87,7 @@ class AnnotatedClass(Protocol[C_co]): Annotations = dict[str, Any] -DEFAULT_LOGGING_CONFIG = { +DEFAULT_LOGGING_CONFIG = { # pragma: no mutate "version": 1, "disable_existing_loggers": False, "filters": { @@ -337,6 +337,7 @@ def __init__( # noqa: PLR0913 log_level: int = logging.INFO, name: str = "annotated_logger", config: dict[str, Any] | Literal[False] | None = None, + # TODO: boolean for correlation_id and then auto generate it ) -> None: """Store the settings. diff --git a/example/logging_config.py b/example/logging_config.py index a79b4ff..fcae428 100644 --- a/example/logging_config.py +++ b/example/logging_config.py @@ -40,7 +40,7 @@ # But, if you want to do that you are likely better off # using a filter not associated with an AnnotatedLogger # like the `logging_config.logger_filter_parens` below - # "annotations": {"decorated": False}, # noqa: ERA001 + "annotations": {"decorated": False}, }, "logging_config.logger_filter_parens": { "()": AnnotatedFilter, @@ -84,7 +84,7 @@ # set by the renamer plugin. Because the handler is using the # annotated_filter the plugings will be run and the fields will be renamed # This also pulls the `runtime` annotation to a specific place in the log - "format": "{time} {level} {name} {runtime} {message}", + "format": "{time} {lvl} {name} {runtime} {message}", "style": "{", }, "logging_config.error_formatter": { diff --git a/test/test_decorator.py b/test/test_decorator.py index 2b79649..01f33ed 100644 --- a/test/test_decorator.py +++ b/test/test_decorator.py @@ -601,5 +601,7 @@ def test_annotated_logger_must_be_first(self): def test_cannot_use_both_formatter_and_config(self): formatter = logging.Formatter("%(time)s %(lvl)s %(name)s %(message)s") - with pytest.raises(ValueError, match="Cannot pass both formatter and config."): + with pytest.raises( + ValueError, match="^Cannot pass both formatter and config.$" + ): AnnotatedLogger(formatter=formatter, config={"logging": "config"}) diff --git a/test/test_logging_config.py b/test/test_logging_config.py index abaa8fc..01fac6e 100644 --- a/test/test_logging_config.py +++ b/test/test_logging_config.py @@ -22,7 +22,7 @@ def test_base_logging(self, annotated_logger_mock): annotated_logger_mock.assert_logged( level, f"this is {level}", - present={"hostname": "my-host"}, + present={"decorated": False}, absent=["weird"], ) From 09235ae11669abf4a7cba289a22f1c8bc459c4d2 Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Mon, 7 Oct 2024 16:01:22 -0400 Subject: [PATCH 07/29] Cleaning up dependencies and fixing a mutation --- annotated_logger/__init__.py | 2 +- pyproject.toml | 1 + requirements/requirements-dev.txt | 8 +++++++- test/test_plugins.py | 6 ++++-- 4 files changed, 13 insertions(+), 4 deletions(-) diff --git a/annotated_logger/__init__.py b/annotated_logger/__init__.py index f42e4dd..031431c 100644 --- a/annotated_logger/__init__.py +++ b/annotated_logger/__init__.py @@ -28,7 +28,7 @@ if TYPE_CHECKING: # pragma: no cover from collections.abc import MutableMapping -VERSION = "1.1.3" # pragma: no mutate +VERSION = "1.2.0" # pragma: no mutate T = TypeVar("T") P = ParamSpec("P") diff --git a/pyproject.toml b/pyproject.toml index 7e4b45e..e36c5d8 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -61,6 +61,7 @@ dependencies = [ "pyright", "pytest", "pytest-cov", + "pytest-forked", "pytest-freezer", "pytest-github-actions-annotate-failures", "pytest-mock", diff --git a/requirements/requirements-dev.txt b/requirements/requirements-dev.txt index ad30a36..182244c 100644 --- a/requirements/requirements-dev.txt +++ b/requirements/requirements-dev.txt @@ -7,14 +7,15 @@ # - pyright # - pytest # - pytest-cov +# - pytest-forked # - pytest-freezer # - pytest-github-actions-annotate-failures # - pytest-mock # - requests-mock # - ruff # - typing_extensions -# - pychoir # - makefun +# - pychoir # - python-json-logger # - requests # @@ -69,6 +70,8 @@ pony==0.7.17 # via mutmut pre-commit==3.7.1 # via hatch.envs.dev +py==1.11.0 + # via pytest-forked pychoir==0.0.27 # via hatch.envs.dev pyright==1.1.376 @@ -77,11 +80,14 @@ pytest==8.2.2 # via # hatch.envs.dev # pytest-cov + # pytest-forked # pytest-freezer # pytest-github-actions-annotate-failures # pytest-mock pytest-cov==5.0.0 # via hatch.envs.dev +pytest-forked==1.6.0 + # via hatch.envs.dev pytest-freezer==0.4.8 # via hatch.envs.dev pytest-github-actions-annotate-failures==0.2.0 diff --git a/test/test_plugins.py b/test/test_plugins.py index 3559fb3..1376ab5 100644 --- a/test/test_plugins.py +++ b/test/test_plugins.py @@ -208,7 +208,7 @@ def test_field_missing_strict(self, annotated_logger_mock): def test_field_missing_not_strict(self, annotated_logger_mock): annotate_logs = AnnotatedLogger( - plugins=[RenamerPlugin(strict=False, made_up_field="some_other_field")], + plugins=[RenamerPlugin(made_up_field="some_other_field")], name="annotated_logger.test_plugins", config=False, ).annotate_logs @@ -217,7 +217,9 @@ def test_field_missing_not_strict(self, annotated_logger_mock): wrapped() record = annotated_logger_mock.records[0] - with pytest.raises(AttributeError): + with pytest.raises( + AttributeError, match="'LogRecord' object has no attribute 'failed_plugins'" + ): _ = record.failed_plugins From 9f6db6865bb0a94f798e1e5577419bc5d17f444b Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Mon, 7 Oct 2024 16:54:33 -0400 Subject: [PATCH 08/29] Fixing up CI and mutations --- .github/workflows/pytest.yaml | 5 ++++- annotated_logger/__init__.py | 13 ++++++------- annotated_logger/mocks.py | 20 ++++++++------------ example/logging_config.py | 15 +++++++-------- test/test_logging_config.py | 8 ++++++-- 5 files changed, 31 insertions(+), 30 deletions(-) diff --git a/.github/workflows/pytest.yaml b/.github/workflows/pytest.yaml index 9b2ae97..6c1c201 100644 --- a/.github/workflows/pytest.yaml +++ b/.github/workflows/pytest.yaml @@ -12,7 +12,10 @@ jobs: runs-on: ${{ matrix.os }} strategy: matrix: - os: [ubuntu-latest, macos-latest, windows-latest] + # pytest-forked does not work on windows and we currently use it for isolation + # of logging configs as logging.dictConfig has a setting to not disable old loggers + # but, does seem to trample old handlers, filters and formatters + os: [ubuntu-latest, macos-latest] python-version: ["3.9", "3.10", "3.11", "pypy3.9", "pypy3.10"] exclude: - os: macos-latest diff --git a/annotated_logger/__init__.py b/annotated_logger/__init__.py index 031431c..88c6b9e 100644 --- a/annotated_logger/__init__.py +++ b/annotated_logger/__init__.py @@ -87,12 +87,12 @@ class AnnotatedClass(Protocol[C_co]): Annotations = dict[str, Any] -DEFAULT_LOGGING_CONFIG = { # pragma: no mutate +DEFAULT_LOGGING_CONFIG = { "version": 1, - "disable_existing_loggers": False, + "disable_existing_loggers": False, # pragma: no mutate "filters": { "annotated_filter": { - "annotated_filter": True, + "annotated_filter": True, # pragma: no mutate } }, "handlers": { @@ -104,11 +104,11 @@ class AnnotatedClass(Protocol[C_co]): }, "formatters": { "annotated_formatter": { - "class": "pythonjsonlogger.jsonlogger.JsonFormatter", + "class": "pythonjsonlogger.jsonlogger.JsonFormatter", # pragma: no mutate # Note that this format string uses `time` and `level` which are # set by the renamer plugin. Because the handler is using the # annotated_filter the plugings will be run and the fields will be renamed - "format": "{created} {levelname} {name} {message}", + "format": "{created} {levelname} {name} {message}", # pragma: no mutate "style": "{", }, }, @@ -116,7 +116,7 @@ class AnnotatedClass(Protocol[C_co]): "annotated_logger": { "level": "DEBUG", "handlers": ["annotated_handler"], - "propagate": False, + "propagate": False, # pragma: no mutate }, }, } @@ -337,7 +337,6 @@ def __init__( # noqa: PLR0913 log_level: int = logging.INFO, name: str = "annotated_logger", config: dict[str, Any] | Literal[False] | None = None, - # TODO: boolean for correlation_id and then auto generate it ) -> None: """Store the settings. diff --git a/annotated_logger/mocks.py b/annotated_logger/mocks.py index caad756..93f80a8 100644 --- a/annotated_logger/mocks.py +++ b/annotated_logger/mocks.py @@ -106,18 +106,14 @@ def _check_record_matches( record: logging.LogRecord, ) -> list[str]: differences = [] - if "levelname" in record.__dict__: - level = record.levelname - elif "level" in record.__dict__: - level = record.level # pyright: ignore[reportAttributeAccessIssue] - # If you have removed levelname and levelno and didn't add level... good luck - else: - level = { - logging.DEBUG: "DEBUG", - logging.INFO: "INFO", - logging.WARNING: "WARNING", - logging.ERROR: "ERROR", - }[record.levelno] + # `levelname` is often renamed. But, `levelno` shouldn't be touched as often + # So, don't try to guess what the level name is, just use the levelno. + level = { + logging.DEBUG: "DEBUG", + logging.INFO: "INFO", + logging.WARNING: "WARNING", + logging.ERROR: "ERROR", + }[record.levelno] actual = { "level": level, "msg": record.msg, diff --git a/example/logging_config.py b/example/logging_config.py index fcae428..a888cb4 100644 --- a/example/logging_config.py +++ b/example/logging_config.py @@ -40,11 +40,11 @@ # But, if you want to do that you are likely better off # using a filter not associated with an AnnotatedLogger # like the `logging_config.logger_filter_parens` below - "annotations": {"decorated": False}, + "annotations": {"config_based_filter": True}, }, "logging_config.logger_filter_parens": { "()": AnnotatedFilter, - "annotations": {"decorated": False}, + "annotations": {"decorated": False, "class_based_filter": True}, "class_annotations": {}, "runtime_annotations": {"custom_runtime": lambda _record: True}, "plugins": [BasePlugin()], @@ -80,10 +80,9 @@ "formatters": { "logging_config.annotated_formatter": { "class": "pythonjsonlogger.jsonlogger.JsonFormatter", - # Note that this format string uses `time` and `level` which are - # set by the renamer plugin. Because the handler is using the - # annotated_filter the plugings will be run and the fields will be renamed - # This also pulls the `runtime` annotation to a specific place in the log + # Note that this format string uses `time` which is set by the renamer + # plugin. It also has `lvl` which is there strictly to test our fallback + # to using `levelno` in the mocks to determine level. "format": "{time} {lvl} {name} {runtime} {message}", "style": "{", }, @@ -92,7 +91,7 @@ "style": "{", }, "logging_config.long_formatter": { - "format": "{level} Long message, may be split {message}", + "format": "{lvl} Long message, may be split {message}", # 3.12 added support for defaults in dict configs # With that we can add the format and defaults below # for a more realistic example. Not all of the messages @@ -143,7 +142,7 @@ def runtime(_record: logging.LogRecord) -> str: annotated_logger = AnnotatedLogger( annotations={"hostname": "my-host"}, runtime_annotations={"runtime": runtime}, - plugins=[RenamerPlugin(time="created", level="levelname")], + plugins=[RenamerPlugin(time="created", lvl="levelname")], log_level=logging.DEBUG, max_length=200, name="annotated_logger.logging_config", diff --git a/test/test_logging_config.py b/test/test_logging_config.py index 01fac6e..75987c6 100644 --- a/test/test_logging_config.py +++ b/test/test_logging_config.py @@ -22,8 +22,12 @@ def test_base_logging(self, annotated_logger_mock): annotated_logger_mock.assert_logged( level, f"this is {level}", - present={"decorated": False}, - absent=["weird"], + present={ + "decorated": False, + "config_based_filter": True, + "class_based_filter": True, + }, + absent=["weird", "hostname"], ) def test_annotated_logging(self, annotated_logger_mock: AnnotatedLogMock): From 29fedebbd9050d7afd862d1e27e02075e3e1083d Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Mon, 7 Oct 2024 17:01:53 -0400 Subject: [PATCH 09/29] Adding codeql --- .github/codeql/codeql-config.yaml | 3 +++ .github/workflows/codeql.yaml | 38 +++++++++++++++++++++++++++++++ 2 files changed, 41 insertions(+) create mode 100644 .github/codeql/codeql-config.yaml create mode 100644 .github/workflows/codeql.yaml diff --git a/.github/codeql/codeql-config.yaml b/.github/codeql/codeql-config.yaml new file mode 100644 index 0000000..85202cd --- /dev/null +++ b/.github/codeql/codeql-config.yaml @@ -0,0 +1,3 @@ +paths-ignore: + - test + - vendor diff --git a/.github/workflows/codeql.yaml b/.github/workflows/codeql.yaml new file mode 100644 index 0000000..e69eb3e --- /dev/null +++ b/.github/workflows/codeql.yaml @@ -0,0 +1,38 @@ +name: "CodeQL" + +"on": + push: + branches: [ main ] + pull_request: + branches: [ main ] + schedule: + - cron: '26 20 * * 5' + +jobs: + analyze: + name: Analyze + runs-on: ubuntu-latest + permissions: + actions: read + contents: read + security-events: write + + strategy: + fail-fast: false + matrix: + language: [ "python" ] + + steps: + - name: Checkout repository + uses: actions/checkout@v4 + + - name: Initialize CodeQL + uses: github/codeql-action/init@v3 + with: + languages: ${{ matrix.language }} + queries: security-and-quality + config-file: ./.github/codeql/codeql-config.yml + setup-python-dependencies: false + + - name: Perform CodeQL Analysis + uses: github/codeql-action/analyze@v3 From 3cbe2493e3436d8af3f0f6a66085f4754d22eb2b Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Mon, 7 Oct 2024 17:08:34 -0400 Subject: [PATCH 10/29] yaml >> yml --- .github/workflows/codeql.yaml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/codeql.yaml b/.github/workflows/codeql.yaml index e69eb3e..87bebc8 100644 --- a/.github/workflows/codeql.yaml +++ b/.github/workflows/codeql.yaml @@ -31,7 +31,7 @@ jobs: with: languages: ${{ matrix.language }} queries: security-and-quality - config-file: ./.github/codeql/codeql-config.yml + config-file: ./.github/codeql/codeql-config.yaml setup-python-dependencies: false - name: Perform CodeQL Analysis From b9d11bdf5a61fc13d0bab7b7708dfb059af044f8 Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Mon, 7 Oct 2024 17:46:07 -0400 Subject: [PATCH 11/29] Killing last mutation --- test/test_logging_config.py | 1 + 1 file changed, 1 insertion(+) diff --git a/test/test_logging_config.py b/test/test_logging_config.py index 75987c6..21c1ffa 100644 --- a/test/test_logging_config.py +++ b/test/test_logging_config.py @@ -26,6 +26,7 @@ def test_base_logging(self, annotated_logger_mock): "decorated": False, "config_based_filter": True, "class_based_filter": True, + "lvl": level.upper(), }, absent=["weird", "hostname"], ) From 0f952234c93dbe669a09c4804846a23cc8896801 Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Mon, 7 Oct 2024 18:06:03 -0400 Subject: [PATCH 12/29] Adding/updating OSS documentation --- .github/workflows/pytest.yaml | 2 +- CODE_OF_CONDUCT.md | 74 +++++++++++++++++++++++++++++++++++ CONTRIBUTING.md | 43 ++++++++++++++++++++ README.md | 21 ++++++---- SECURITY.md | 31 +++++++++++++++ SUPPORT.md | 13 ++++++ 6 files changed, 176 insertions(+), 8 deletions(-) create mode 100644 CODE_OF_CONDUCT.md create mode 100644 CONTRIBUTING.md create mode 100644 SECURITY.md create mode 100644 SUPPORT.md diff --git a/.github/workflows/pytest.yaml b/.github/workflows/pytest.yaml index 6c1c201..d43046e 100644 --- a/.github/workflows/pytest.yaml +++ b/.github/workflows/pytest.yaml @@ -16,7 +16,7 @@ jobs: # of logging configs as logging.dictConfig has a setting to not disable old loggers # but, does seem to trample old handlers, filters and formatters os: [ubuntu-latest, macos-latest] - python-version: ["3.9", "3.10", "3.11", "pypy3.9", "pypy3.10"] + python-version: ["3.9", "3.10", "3.11", "3.12", "pypy3.9", "pypy3.10"] exclude: - os: macos-latest python-version: "3.9" diff --git a/CODE_OF_CONDUCT.md b/CODE_OF_CONDUCT.md new file mode 100644 index 0000000..6dc4b12 --- /dev/null +++ b/CODE_OF_CONDUCT.md @@ -0,0 +1,74 @@ +# Contributor Covenant Code of Conduct + +## Our Pledge + +In the interest of fostering an open and welcoming environment, we as +contributors and maintainers pledge to making participation in our project and +our community a harassment-free experience for everyone, regardless of age, body +size, disability, ethnicity, gender identity and expression, level of experience, +nationality, personal appearance, race, religion, or sexual identity and +orientation. + +## Our Standards + +Examples of behavior that contributes to creating a positive environment +include: + +* Using welcoming and inclusive language +* Being respectful of differing viewpoints and experiences +* Gracefully accepting constructive criticism +* Focusing on what is best for the community +* Showing empathy towards other community members + +Examples of unacceptable behavior by participants include: + +* The use of sexualized language or imagery and unwelcome sexual attention or +advances +* Trolling, insulting/derogatory comments, and personal or political attacks +* Public or private harassment +* Publishing others' private information, such as a physical or electronic + address, without explicit permission +* Other conduct which could reasonably be considered inappropriate in a + professional setting + +## Our Responsibilities + +Project maintainers are responsible for clarifying the standards of acceptable +behavior and are expected to take appropriate and fair corrective action in +response to any instances of unacceptable behavior. + +Project maintainers have the right and responsibility to remove, edit, or +reject comments, commits, code, wiki edits, issues, and other contributions +that are not aligned to this Code of Conduct, or to ban temporarily or +permanently any contributor for other behaviors that they deem inappropriate, +threatening, offensive, or harmful. + +## Scope + +This Code of Conduct applies both within project spaces and in public spaces +when an individual is representing the project or its community. Examples of +representing a project or community include using an official project e-mail +address, posting via an official social media account, or acting as an appointed +representative at an online or offline event. Representation of a project may be +further defined and clarified by project maintainers. + +## Enforcement + +Instances of abusive, harassing, or otherwise unacceptable behavior may be +reported by contacting the project team at . All +complaints will be reviewed and investigated and will result in a response that +is deemed necessary and appropriate to the circumstances. The project team is +obligated to maintain confidentiality with regard to the reporter of an incident. +Further details of specific enforcement policies may be posted separately. + +Project maintainers who do not follow or enforce the Code of Conduct in good +faith may face temporary or permanent repercussions as determined by other +members of the project's leadership. + +## Attribution + +This Code of Conduct is adapted from the [Contributor Covenant][homepage], version 1.4, +available at [http://contributor-covenant.org/version/1/4][version] + +[homepage]: http://contributor-covenant.org +[version]: http://contributor-covenant.org/version/1/4/ diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md new file mode 100644 index 0000000..4393ba0 --- /dev/null +++ b/CONTRIBUTING.md @@ -0,0 +1,43 @@ +## Contributing + +[fork]: https://github.com/github/annotated-logger/fork +[pr]: https://github.com/github/annotated-logger/compare +[style]: https://docs.astral.sh/ruff/ + +Hi there! We're thrilled that you'd like to contribute to this project. Your help is essential for keeping it great. + +Contributions to this project are [released](https://help.github.com/articles/github-terms-of-service/#6-contributions-under-repository-license) to the public under the [project's open source license](LICENSE.txt). + +Please note that this project is released with a [Contributor Code of Conduct](CODE_OF_CONDUCT.md). By participating in this project you agree to abide by its terms. + +## Developing a fix/feature + +Annotated Logger uses `ruff`, `pytest`, `pyright` and `mutmut` for testing and linting. It uses [`hatch`](https://github.com/pypa/hatch) as a project manager to build and install dependencies. When developing locally it's suggested that you ensure that your editor supports `ruff` and `pyright` for inline linting. The `pytest` test suite is very quick and should be run frequently. (`mutmut`)[https://github.com/boxed/mutmut] is a mutation testing tool and is fairly slow as it runs the other three tools hundreds of times after making minor tweaks to the code. It will typically be run only once development is complete to ensure everything is fully tested. + +`script/mutmut_runner` is what `mutmut` uses to see if the mutation fails, however, it's also quite useful on it's own as it runs `ruff`, `pytest` and `pyright` exiting as soon as anything fails, so it makes a good sanity check. + +In addition to the tests and linting above all PRs will compare the version number in \_\_init\_\_.py with the version in `main` to ensure that new PRs results in new versions. + +## Submitting a pull request + +1. [Fork][fork] and clone the repository +1. Configure and install the dependencies: `script/bootstrap` +1. Make sure the tests pass on your machine: `hatch run dev:test` +1. Make sure linting passes: `hatch run dev:lint` and `hatch run dev:typing` +1. Create a new branch: `git checkout -b my-branch-name` +1. Make your change, add tests, and make sure the tests still pass +1. Push to your fork and [submit a pull request][pr] +1. Pat yourself on the back and wait for your pull request to be reviewed and merged. + +Here are a few things you can do that will increase the likelihood of your pull request being accepted: + +- Follow the [style guide][style]. +- Write tests. +- Keep your change as focused as possible. If there are multiple changes you would like to make that are not dependent upon each other, consider submitting them as separate pull requests. +- Write a [good commit message](http://tbaggery.com/2008/04/19/a-note-about-git-commit-messages.html). + +## Resources + +- [How to Contribute to Open Source](https://opensource.guide/how-to-contribute/) +- [Using Pull Requests](https://help.github.com/articles/about-pull-requests/) +- [GitHub Help](https://help.github.com) diff --git a/README.md b/README.md index 45422a3..6089307 100644 --- a/README.md +++ b/README.md @@ -1,8 +1,18 @@ # Annotated Logger + +[contribution]: https://github.com/github/annotated-logger/blob/main/CONTRIBUTING.md + [![Coverage badge](https://github.com/github/logger-decorator/raw/python-coverage-comment-action-data/badge.svg)](https://github.com/github/logger-decorator/tree/python-coverage-comment-action-data) [![Ruff](https://img.shields.io/endpoint?url=https://raw.githubusercontent.com/astral-sh/ruff/main/assets/badge/v2.json)](https://github.com/astral-sh/ruff) [![Checked with pyright](https://microsoft.github.io/pyright/img/pyright_badge.svg)](https://microsoft.github.io/pyright/) The `annotated-logger` package provides a decorator that can inject a annotatable logger object into a method or class. This logger object is a drop in replacement for `logging.logger` with additional functionality. +## Background + +Annotated Logger is actively used by GitHub's Vulnerability Management team to help to easily add context to our logs in splunk. It is more or less feature complete for our current use cases, but we will add additional features/fixes as we discover a need for them. But, we'd love feature requests, bug report and or PRs for either (see our [contribution guidelines][contribution] for more information if you wish to contribute). + +## Requirements +Annotated Logger is a Python package. It should work on any version of Python 3, but it is currently tested on 3.9 and higher. + ## Usage The `annotated-logger` package allows you to decorate a function so that the start and end of that function is logged as well as allowing that function to request an `annotated_logger` object which can be used as if it was a standard python `logger`. Additionally, the `annotated_logger` object will have added annotations based on the method it requested from, any other annotations that were configured ahead of time and any annotations that were added prior to a log being made. Finally, any uncaught exceptions in a decorated method will be logged and re-raised, which allows you to when and how a method ended regardless of if it was successful or not. @@ -28,12 +38,9 @@ foo("this is the bar parameter") The example directory has a few files that exercise all of the features of the annotated-logger package. The `Calculator` class is the most fully featured example (but not a fully featured calculator :wink:). The `logging_config` example shows how to configure a logger via a dictConfig, like django uses. It also shows some of the interactions that can exist between a `logging` logger and an `annotated_logger` if `logging` is configured to use the annotated logger filter. +## License +This project is licensed under the terms of the MIT open source license. Please refer to MIT for the full terms. -## Contributing - -Annotated Logger uses `ruff`, `pytest`, `pyright` and `mutmut` for testing and linting. It uses [`hatch`](https://github.com/pypa/hatch) as a project manager to build and install dependencies. When developing locally it's suggested that you ensure that your editor supports `ruff` and `pyright` for inline linting. The `pytest` test suite is very quick and should be run frequently. (`mutmut`)[https://github.com/boxed/mutmut] is a mutation testing tool and is fairly slow as it runs the other three tools hundreds of times after making minor tweaks to the code. It will typically be run only once development is complete to ensure everything is fully tested. - -`script/mutmut_runner` is what `mutmut` uses to see if the mutation fails, however, it's also quite useful on it's own as it runs `ruff`, `pytest` and `pyright` exiting as soon as anything fails, so it makes a good sanity check. - -In addition to the tests and linting above all PRs will compare the version number in \_\_init\_\_.py with the version in `main` to ensure that new PRs results in new versions. +## Maintainers +This project is primarily maintained by `crimsonknave` on behalf of GitHub's Vulnerability Management team as it was initially developed for our internal use. diff --git a/SECURITY.md b/SECURITY.md new file mode 100644 index 0000000..abe011d --- /dev/null +++ b/SECURITY.md @@ -0,0 +1,31 @@ +Thanks for helping make GitHub safe for everyone. + +# Security + +GitHub takes the security of our software products and services seriously, including all of the open source code repositories managed through our GitHub organizations, such as [GitHub](https://github.com/GitHub). + +Even though [open source repositories are outside of the scope of our bug bounty program](https://bounty.github.com/index.html#scope) and therefore not eligible for bounty rewards, we will ensure that your finding gets passed along to the appropriate maintainers for remediation. + +## Reporting Security Issues + +If you believe you have found a security vulnerability in any GitHub-owned repository, please report it to us through coordinated disclosure. + +**Please do not report security vulnerabilities through public GitHub issues, discussions, or pull requests.** + +Instead, please send an email to opensource-security[@]github.com. + +Please include as much of the information listed below as you can to help us better understand and resolve the issue: + + * The type of issue (e.g., buffer overflow, SQL injection, or cross-site scripting) + * Full paths of source file(s) related to the manifestation of the issue + * The location of the affected source code (tag/branch/commit or direct URL) + * Any special configuration required to reproduce the issue + * Step-by-step instructions to reproduce the issue + * Proof-of-concept or exploit code (if possible) + * Impact of the issue, including how an attacker might exploit the issue + +This information will help us triage your report more quickly. + +## Policy + +See [GitHub's Safe Harbor Policy](https://docs.github.com/en/site-policy/security-policies/github-bug-bounty-program-legal-safe-harbor#1-safe-harbor-terms) diff --git a/SUPPORT.md b/SUPPORT.md new file mode 100644 index 0000000..45f5139 --- /dev/null +++ b/SUPPORT.md @@ -0,0 +1,13 @@ +# Support + +## How to file issues and get help + +This project uses GitHub issues to track bugs and feature requests. Please search the existing issues before filing new issues to avoid duplicates. For new issues, file your bug or feature request as a new issue. + +For help or questions about using this project, please create an issue or discussion. + +- Annotated Logger is under active development and maintained by GitHub staff **AND THE COMMUNITY**. We will do our best to respond to support, feature requests, and community questions in a timely manner. + +## GitHub Support Policy + +Support for this project is limited to the resources listed above. From 56adb9bdd1241577f20313f16353547a88a2d8d8 Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Wed, 9 Oct 2024 15:53:58 -0400 Subject: [PATCH 13/29] Removing custom codeql scanning --- .github/codeql/codeql-config.yaml | 3 --- .github/workflows/codeql.yaml | 38 ------------------------------- 2 files changed, 41 deletions(-) delete mode 100644 .github/codeql/codeql-config.yaml delete mode 100644 .github/workflows/codeql.yaml diff --git a/.github/codeql/codeql-config.yaml b/.github/codeql/codeql-config.yaml deleted file mode 100644 index 85202cd..0000000 --- a/.github/codeql/codeql-config.yaml +++ /dev/null @@ -1,3 +0,0 @@ -paths-ignore: - - test - - vendor diff --git a/.github/workflows/codeql.yaml b/.github/workflows/codeql.yaml deleted file mode 100644 index 87bebc8..0000000 --- a/.github/workflows/codeql.yaml +++ /dev/null @@ -1,38 +0,0 @@ -name: "CodeQL" - -"on": - push: - branches: [ main ] - pull_request: - branches: [ main ] - schedule: - - cron: '26 20 * * 5' - -jobs: - analyze: - name: Analyze - runs-on: ubuntu-latest - permissions: - actions: read - contents: read - security-events: write - - strategy: - fail-fast: false - matrix: - language: [ "python" ] - - steps: - - name: Checkout repository - uses: actions/checkout@v4 - - - name: Initialize CodeQL - uses: github/codeql-action/init@v3 - with: - languages: ${{ matrix.language }} - queries: security-and-quality - config-file: ./.github/codeql/codeql-config.yaml - setup-python-dependencies: false - - - name: Perform CodeQL Analysis - uses: github/codeql-action/analyze@v3 From f4f5cf29790b1ea089843be8e162342267148441 Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Thu, 10 Oct 2024 14:13:33 -0400 Subject: [PATCH 14/29] Too large commit: Add actions plugin and lots of rework to solve some logging config weirdness it revealed --- annotated_logger/__init__.py | 60 +------- annotated_logger/filter.py | 63 ++++++++ annotated_logger/plugins.py | 70 ++++++++- example/actions.py | 43 ++++++ example/logging_config.py | 10 ++ pyproject.toml | 8 +- requirements/requirements-dev.txt | 10 +- test/conftest.py | 41 +++++ test/test_decorator.py | 243 ++++++++++++++++-------------- test/test_logging_config.py | 1 + test/test_mocks.py | 39 ++--- test/test_plugins.py | 12 ++ 12 files changed, 397 insertions(+), 203 deletions(-) create mode 100644 annotated_logger/filter.py create mode 100644 example/actions.py diff --git a/annotated_logger/__init__.py b/annotated_logger/__init__.py index 88c6b9e..82d87ad 100644 --- a/annotated_logger/__init__.py +++ b/annotated_logger/__init__.py @@ -23,6 +23,7 @@ from makefun import wraps +from annotated_logger.filter import AnnotatedFilter from annotated_logger.plugins import BasePlugin if TYPE_CHECKING: # pragma: no cover @@ -98,16 +99,12 @@ class AnnotatedClass(Protocol[C_co]): "handlers": { "annotated_handler": { "class": "logging.StreamHandler", - "filters": ["annotated_filter"], "formatter": "annotated_formatter", }, }, "formatters": { "annotated_formatter": { "class": "pythonjsonlogger.jsonlogger.JsonFormatter", # pragma: no mutate - # Note that this format string uses `time` and `level` which are - # set by the renamer plugin. Because the handler is using the - # annotated_filter the plugings will be run and the fields will be renamed "format": "{created} {levelname} {name} {message}", # pragma: no mutate "style": "{", }, @@ -167,61 +164,6 @@ def __next__(self) -> T: return value -class AnnotatedFilter(logging.Filter): - """Filter class that stores the annotations and plugins.""" - - def __init__( - self, - annotations: Annotations, - runtime_annotations: Annotations, - class_annotations: Annotations, - plugins: list[BasePlugin], - ) -> None: - """Store the annotations, attributes and plugins.""" - self.annotations = annotations - self.class_annotations = class_annotations - self.runtime_annotations = runtime_annotations or {} - self.plugins = plugins - - # This allows plugins to determine what fields were added by the user - # vs the ones native to the log record - # TODO(crimsonknave): Make a test for this # noqa: TD003, FIX002 - self.base_attributes = logging.makeLogRecord({}).__dict__ # pragma: no mutate - - def _all_annotations(self, record: logging.LogRecord) -> Annotations: - annotations = {} - # Using copy might be better, but, we don't want to add - # the runtime annotations to the stored annotations - annotations.update(self.class_annotations) - annotations.update(self.annotations) - for key, function in self.runtime_annotations.items(): - annotations[key] = function(record) - annotations["annotated"] = True - return annotations - - def filter(self, record: logging.LogRecord) -> bool: - """Add the annotations to the record and allow plugins to filter the record. - - The `filter` method is called on each plugin in the order they are listed. - The plugin is then able to maniuplate the record object before the next plugin - sees it. Returning False from the filter method will stop the evaluation and - the log record won't be emitted. - """ - record.__dict__.update(self._all_annotations(record)) - for plugin in self.plugins: - try: - result = plugin.filter(record) - except Exception: # noqa: BLE001 - failed_plugins = record.__dict__.get("failed_plugins", []) - failed_plugins.append(str(plugin.__class__)) - record.__dict__["failed_plugins"] = failed_plugins - result = True - - if not result: - return False - return True - - class AnnotatedAdapter(logging.LoggerAdapter): # pyright: ignore[reportMissingTypeArgument] """Adapter that provides extra methods.""" diff --git a/annotated_logger/filter.py b/annotated_logger/filter.py new file mode 100644 index 0000000..d2c3c2d --- /dev/null +++ b/annotated_logger/filter.py @@ -0,0 +1,63 @@ +from __future__ import annotations + +import logging +from typing import Any + +import annotated_logger + +Annotations = dict[str, Any] + + +class AnnotatedFilter(logging.Filter): + """Filter class that stores the annotations and plugins.""" + + def __init__( + self, + annotations: Annotations | None = None, + runtime_annotations: Annotations | None = None, + class_annotations: Annotations | None = None, + plugins: list[annotated_logger.BasePlugin] | None = None, + ) -> None: + """Store the annotations, attributes and plugins.""" + self.annotations = annotations or {} + self.class_annotations = class_annotations or {} + self.runtime_annotations = runtime_annotations or {} + self.plugins = plugins or [annotated_logger.BasePlugin()] + + # This allows plugins to determine what fields were added by the user + # vs the ones native to the log record + # TODO(crimsonknave): Make a test for this # noqa: TD003, FIX002 + self.base_attributes = logging.makeLogRecord({}).__dict__ # pragma: no mutate + + def _all_annotations(self, record: logging.LogRecord) -> Annotations: + annotations = {} + # Using copy might be better, but, we don't want to add + # the runtime annotations to the stored annotations + annotations.update(self.class_annotations) + annotations.update(self.annotations) + for key, function in self.runtime_annotations.items(): + annotations[key] = function(record) + annotations["annotated"] = True + return annotations + + def filter(self, record: logging.LogRecord) -> bool: + """Add the annotations to the record and allow plugins to filter the record. + + The `filter` method is called on each plugin in the order they are listed. + The plugin is then able to maniuplate the record object before the next plugin + sees it. Returning False from the filter method will stop the evaluation and + the log record won't be emitted. + """ + record.__dict__.update(self._all_annotations(record)) + for plugin in self.plugins: + try: + result = plugin.filter(record) + except Exception: # noqa: BLE001 + failed_plugins = record.__dict__.get("failed_plugins", []) + failed_plugins.append(str(plugin.__class__)) + record.__dict__["failed_plugins"] = failed_plugins + result = True + + if not result: + return False + return True diff --git a/annotated_logger/plugins.py b/annotated_logger/plugins.py index d72b14e..461e584 100644 --- a/annotated_logger/plugins.py +++ b/annotated_logger/plugins.py @@ -1,13 +1,14 @@ from __future__ import annotations import contextlib +import logging from typing import TYPE_CHECKING from requests.exceptions import HTTPError -if TYPE_CHECKING: # pragma: no cover - import logging +from annotated_logger.filter import AnnotatedFilter +if TYPE_CHECKING: # pragma: no cover from annotated_logger import AnnotatedAdapter @@ -122,3 +123,68 @@ def delete_keys_nested( record.__dict__ = delete_keys_nested(record.__dict__, self.keys_to_remove) return True + + +class GitHubActionsPlugin(BasePlugin): + """Plugin that will format log messages for actions annotations.""" + + def __init__(self, annotation_level: int) -> None: + """Save the annotation level.""" + self.annotation_level = annotation_level + self.base_attributes = logging.makeLogRecord({}).__dict__ # pragma: no mutate + self.attributes_to_exclude = {"annotated"} + + def filter(self, record: logging.LogRecord) -> bool: + """Set the actions command to be an annotation if desired.""" + if record.levelno < self.annotation_level: + return False + + added_attributes = { + k: v + for k, v in record.__dict__.items() + if k not in self.base_attributes and k not in self.attributes_to_exclude + } + record.__dict__["added_attributes"] = added_attributes + name = record.levelname.lower() + if name == "info": # pragma: no cover + name = "notice" + record.__dict__["github_annotation"] = f"{name}::" + + return True + + def logging_config(self) -> dict[str, dict[str, object]]: + """Generate the default logging config for the plugin.""" + return { + "handlers": { + "actions_handler": { + "class": "logging.StreamHandler", + "filters": ["actions_filter"], + "formatter": "actions_formatter", + }, + }, + "filters": { + "actions_filter": { + "()": AnnotatedFilter, + "plugins": [ + BasePlugin(), + self, + ], + }, + }, + "formatters": { + "actions_formatter": { + "format": "{github_annotation} {message} - {added_attributes}", + "style": "{", + }, + }, + "loggers": { + "annotated_logger.actions": { + "level": "DEBUG", + "handlers": [ + # This is from the default logging config + "annotated_handler", + "actions_handler", + ], + }, + }, + } diff --git a/example/actions.py b/example/actions.py new file mode 100644 index 0000000..73c57e7 --- /dev/null +++ b/example/actions.py @@ -0,0 +1,43 @@ +import logging +from copy import deepcopy + +from annotated_logger import ( + DEFAULT_LOGGING_CONFIG, + AnnotatedAdapter, + AnnotatedLogger, +) +from annotated_logger.plugins import GitHubActionsPlugin + +actions_plugin = GitHubActionsPlugin(annotation_level=logging.INFO) + +LOGGING = deepcopy(DEFAULT_LOGGING_CONFIG) + +# The GitHubActionsPlugin provides a `logging_config` method that returns some +# defaults that will annotate at the info (notice) and above. +# Making a copy of the default logging config and updating with this +# lets us keep the standard logger and also annotate in actions. +# But, we need to do it bit by bit so we are updating the loggers and so on +# instead of replacing the loggers. +LOGGING["loggers"].update(actions_plugin.logging_config()["loggers"]) +LOGGING["filters"].update(actions_plugin.logging_config()["filters"]) +LOGGING["handlers"].update(actions_plugin.logging_config()["handlers"]) +LOGGING["formatters"].update(actions_plugin.logging_config()["formatters"]) + +annotated_logger = AnnotatedLogger( + plugins=[ + actions_plugin, + ], + name="annotated_logger.actions", + config=LOGGING, +) + +annotate_logs = annotated_logger.annotate_logs + + +class ActionsExample: + """Example application that is designed to run in actions.""" + + @annotate_logs(_typing_requested=True) + def first_step(self, annotated_logger: AnnotatedAdapter) -> None: + """First step of your action.""" + annotated_logger.info("Step 1 running!") diff --git a/example/logging_config.py b/example/logging_config.py index a888cb4..52adb35 100644 --- a/example/logging_config.py +++ b/example/logging_config.py @@ -57,6 +57,16 @@ }, "logging_config.logger_handler": { "class": "logging.StreamHandler", + # Note that this handler is specifically attached to + # `annotated_logger.logging_config.logger` which we intend to use only as a + # logger not generated by a decorator. If you add filters to a handler that + # will be invoked when logging from a logger generated by the decorator + # AKA, logging via the `annotated_logger` parameter, these filters will + # be applied *after* the filters that are dynamically generated/updated + # and so can override any annotations that share a name. + # In this case, if a function annotated `custom_runtime` or one of the + # other fields set in the filters above, that value would be overridden + # by the value in the filter set in the config. "filters": [ "logging_config.logger_filter", "logging_config.logger_filter_parens", diff --git a/pyproject.toml b/pyproject.toml index e36c5d8..359603a 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -61,10 +61,10 @@ dependencies = [ "pyright", "pytest", "pytest-cov", - "pytest-forked", "pytest-freezer", "pytest-github-actions-annotate-failures", "pytest-mock", + "pytest-randomly", "requests-mock", "ruff", "typing_extensions", @@ -92,11 +92,9 @@ reportMissingTypeArgument = true [tool.pytest.ini_options] # -p no:annotated_logger disables the plugin so that we can request it conftest.py -# get coverage correctly, users will not have to do this. +# to get coverage correctly, users will not have to do this. # See https://github.com/pytest-dev/pytest/issues/935 -# --forked will run each test in it's own process, which prevents the logging configs -# from overriding eachother and clobbering the handlers and the like -addopts = "--cov=annotated_logger --cov=example --cov-report html --cov-report term -p no:annotated_logger --forked" +addopts = "--cov=annotated_logger --cov=example --cov-report html --cov-report term -p no:annotated_logger" filterwarnings = [ "error", ] diff --git a/requirements/requirements-dev.txt b/requirements/requirements-dev.txt index 182244c..20f5548 100644 --- a/requirements/requirements-dev.txt +++ b/requirements/requirements-dev.txt @@ -7,10 +7,10 @@ # - pyright # - pytest # - pytest-cov -# - pytest-forked # - pytest-freezer # - pytest-github-actions-annotate-failures # - pytest-mock +# - pytest-randomly # - requests-mock # - ruff # - typing_extensions @@ -70,8 +70,6 @@ pony==0.7.17 # via mutmut pre-commit==3.7.1 # via hatch.envs.dev -py==1.11.0 - # via pytest-forked pychoir==0.0.27 # via hatch.envs.dev pyright==1.1.376 @@ -80,20 +78,20 @@ pytest==8.2.2 # via # hatch.envs.dev # pytest-cov - # pytest-forked # pytest-freezer # pytest-github-actions-annotate-failures # pytest-mock + # pytest-randomly pytest-cov==5.0.0 # via hatch.envs.dev -pytest-forked==1.6.0 - # via hatch.envs.dev pytest-freezer==0.4.8 # via hatch.envs.dev pytest-github-actions-annotate-failures==0.2.0 # via hatch.envs.dev pytest-mock==3.14.0 # via hatch.envs.dev +pytest-randomly==3.15.0 + # via hatch.envs.dev python-dateutil==2.9.0.post0 # via freezegun python-json-logger==2.0.7 diff --git a/test/conftest.py b/test/conftest.py index b49fd19..614d1ef 100644 --- a/test/conftest.py +++ b/test/conftest.py @@ -1,5 +1,15 @@ +from __future__ import annotations + +import importlib + import pytest +import example.actions +import example.api +import example.calculator +import example.default +import example.logging_config + # Due to the lack of config in pytest plugin ordering we have to manually add it here # so that we get coverage on the code correctly. Users will not need to. # See https://github.com/pytest-dev/pytest/issues/935 @@ -9,3 +19,34 @@ @pytest.fixture() def fail_mock(mocker): return mocker.patch("annotated_logger.mocks.pytest.fail") + + +# These fixtures are used in place of importing the classes with +# `from example.api import ApiClient` +# They force the relevant module to be reloaded, which will reset the +# logging config, as it gets clobbered by the most recently imported module +# This is a more complete solution than using `pytest-forked` which only +# fixed the issue if the test file didn't import more than one that conflicted +@pytest.fixture() +def _reload_api(): + importlib.reload(example.api) + + +@pytest.fixture() +def _reload_calculator(): + importlib.reload(example.calculator) + + +@pytest.fixture() +def _reload_default(): + importlib.reload(example.default) + + +@pytest.fixture() +def _reload_actions(): + importlib.reload(example.actions) + + +@pytest.fixture() +def _reload_logging_config(): + importlib.reload(example.logging_config) diff --git a/test/test_decorator.py b/test/test_decorator.py index 01f33ed..166854d 100644 --- a/test/test_decorator.py +++ b/test/test_decorator.py @@ -1,21 +1,26 @@ +from __future__ import annotations + import logging +from typing import TYPE_CHECKING import pytest from pychoir.strings import StartsWith +import example.api +import example.calculator +import example.default import test.demo from annotated_logger import AnnotatedLogger -from annotated_logger.mocks import AnnotatedLogMock -from example.api import ApiClient -from example.calculator import BoomError, Calculator, annotated_logger -from example.default import DefaultExample, var_args_and_kwargs_provided_outer + +if TYPE_CHECKING: + from annotated_logger.mocks import AnnotatedLogMock -class TestAnnotatedLogger: +@pytest.mark.usefixtures("_reload_calculator") +class TestCalculatorExample: # Test logged exceptions with Calculator.divide() - # def test_logged_exception(self, annotated_logger_mock): def test_logged_exception(self, annotated_logger_mock): - calc = Calculator(1, 0) + calc = example.calculator.Calculator(1, 0) with pytest.raises(ZeroDivisionError): calc.divide() @@ -33,7 +38,7 @@ def test_logged_exception(self, annotated_logger_mock): # Test logged attributes with Calculator.add() def test_success_info_false(self, annotated_logger_mock): - calc = Calculator(6, 7) + calc = example.calculator.Calculator(6, 7) calc.add() annotated_logger_mock.assert_logged( "DEBUG", @@ -50,7 +55,7 @@ def test_success_info_false(self, annotated_logger_mock): ) def test_annotate_logger(self, annotated_logger_mock): - calc = Calculator(6, 7) + calc = example.calculator.Calculator(6, 7) calc.add() annotated_logger_mock.assert_logged( "DEBUG", @@ -84,7 +89,7 @@ def test_annotate_logger(self, annotated_logger_mock): ) def test_can_provide_annotated_logger(self, annotated_logger_mock): - calc = Calculator(1, 5) + calc = example.calculator.Calculator(1, 5) answer = calc.power(2, 3) assert answer == 8 annotated_logger_mock.assert_logged( @@ -124,7 +129,7 @@ def test_can_provide_annotated_logger(self, annotated_logger_mock): # Test logger info call with Calculator.add() def test_info(self, annotated_logger_mock): - calc = Calculator(8, 9) + calc = example.calculator.Calculator(8, 9) calc.add() # This also tests the `annotate_logger` method annotated_logger_mock.assert_logged( @@ -153,7 +158,7 @@ def test_info(self, annotated_logger_mock): # Test logger warn call with Calculator.divide() def test_warn(self, annotated_logger_mock): - calc = Calculator(10, 11) + calc = example.calculator.Calculator(10, 11) calc.divide() annotated_logger_mock.assert_logged( @@ -168,7 +173,7 @@ def test_warn(self, annotated_logger_mock): # Test logger error call with Calculator.add() with a bad value def test_error(self, annotated_logger_mock): - calc = Calculator(None, 2) # pyright: ignore[reportArgumentType] + calc = example.calculator.Calculator(None, 2) # pyright: ignore[reportArgumentType] calc.add() annotated_logger_mock.assert_logged( "ERROR", @@ -184,7 +189,7 @@ def test_error(self, annotated_logger_mock): # Test logger exception call with Calculator.inverse() def test_exception(self, annotated_logger_mock): - Calculator(1, 11).inverse(0) + example.calculator.Calculator(1, 11).inverse(0) annotated_logger_mock.assert_logged( "ERROR", "Cannot divide by zero!", @@ -197,7 +202,7 @@ def test_exception(self, annotated_logger_mock): # Test logger debug call with Calculator.subtract() def test_debug(self, annotated_logger_mock): - calc = Calculator(12, 13) + calc = example.calculator.Calculator(12, 13) calc.subtract() annotated_logger_mock.assert_logged( "DEBUG", @@ -212,9 +217,13 @@ def test_debug(self, annotated_logger_mock): def test_runtime_not_cached(self, annotated_logger_mock, mocker): runtime_mock = mocker.Mock(name="runtime_not_cached") runtime_mock.side_effect = ["first", "second", "third", "fourth"] - runtime_annotations = annotated_logger.runtime_annotations - annotated_logger.runtime_annotations = {"runtime": runtime_mock} - calc = Calculator(12, 13) + runtime_annotations = example.calculator.annotated_logger.runtime_annotations + example.calculator.annotated_logger.runtime_annotations = { + "runtime": runtime_mock + } + # Need to use full path as that's what's reloaded. The other tests don't need + # to as they're not mocking the runtime annotations + calc = example.calculator.Calculator(12, 13) calc.subtract() annotated_logger_mock.assert_logged( "DEBUG", @@ -234,15 +243,15 @@ def test_runtime_not_cached(self, annotated_logger_mock, mocker): "runtime": "second", }, ) - annotated_logger.runtime_annotations = runtime_annotations + example.calculator.annotated_logger.runtime_annotations = runtime_annotations def test_raises_type_error_with_too_few_args(self): - calc = Calculator(12, 13) + calc = example.calculator.Calculator(12, 13) with pytest.raises(TypeError): calc.multiply() # pyright: ignore[reportCallIssue] def test_raises_type_error_with_too_many_args(self): - calc = Calculator(12, 13) + calc = example.calculator.Calculator(12, 13) with pytest.raises( TypeError, match=r"^Calculator.subtract\(\) takes 1 positional argument but 2 were given$", @@ -256,7 +265,7 @@ def test_raises_type_error_with_too_many_args(self): # Test list instance in logger with Calculator.pemdas_example() def test_list(self, annotated_logger_mock): - calc = Calculator(12, 1) + calc = example.calculator.Calculator(12, 1) calc.pemdas_example() annotated_logger_mock.assert_logged( "INFO", @@ -273,7 +282,7 @@ def test_list(self, annotated_logger_mock): # Test json formatter with Calculator.is_odd() def test_formatter(self, annotated_logger_mock): - Calculator(1, 9).is_odd(14) + example.calculator.Calculator(1, 9).is_odd(14) annotated_logger_mock.assert_logged( "INFO", "success", @@ -288,7 +297,7 @@ def test_formatter(self, annotated_logger_mock): # Test logging via a log object created with logging.getflogger def test_getlogger_logger(self): - Calculator(1, 10).is_odd(14) + example.calculator.Calculator(1, 10).is_odd(14) def test_function_without_a_parameter(self, annotated_logger_mock): test.demo.function_without_parameters() @@ -316,7 +325,7 @@ def test_function_without_a_parameter(self, annotated_logger_mock): ) def test_iterator(self, annotated_logger_mock): - calc = Calculator(1, 0) + calc = example.calculator.Calculator(1, 0) value = calc.factorial(5) assert value == 120 for i in [1, 2, 3, 4, 5]: @@ -335,7 +344,7 @@ def test_iterator(self, annotated_logger_mock): "level", ["debug", "info", "warning", "error", "exception"] ) def test_sensitive_iterator(self, annotated_logger_mock, level): - calc = Calculator(1, 0) + calc = example.calculator.Calculator(1, 0) value = calc.sensitive_factorial(5, level) five_factorial = 120 assert value == five_factorial @@ -352,22 +361,12 @@ def test_sensitive_iterator(self, annotated_logger_mock, level): count=5, ) - def test_no_annotations(self, annotated_logger_mock): - default = DefaultExample() - default.foo() - annotated_logger_mock.assert_logged( - "info", - "foo", - absent=annotated_logger_mock.ALL, - count=1, - ) - def test_logs_len_if_it_exists(self, annotated_logger_mock): class Weird: def __len__(self): return 999 - @annotated_logger.annotate_logs(_typing_self=False) + @example.calculator.annotated_logger.annotate_logs(_typing_self=False) def test_me(): return Weird() @@ -379,7 +378,7 @@ def test_me(): ) def test_classmethod(self, annotated_logger_mock): - assert Calculator.is_math_cool() is True + assert example.calculator.Calculator.is_math_cool() is True annotated_logger_mock.assert_logged( "INFO", "What a silly question!", absent=["sane", "source"] ) @@ -393,14 +392,14 @@ def test_classmethod(self, annotated_logger_mock): ) def test_pre_call(self, annotated_logger_mock): - calc = Calculator(5, 11) + calc = example.calculator.Calculator(5, 11) calc.divide() annotated_logger_mock.assert_logged( "DEBUG", "start", present={"will_crash": False} ) def test_post_call(self, annotated_logger_mock): - calc = Calculator(5, 11) + calc = example.calculator.Calculator(5, 11) calc.divide() annotated_logger_mock.assert_logged( "info", @@ -409,7 +408,7 @@ def test_post_call(self, annotated_logger_mock): ) def test_post_call_exception(self, annotated_logger_mock): - calc = Calculator(5, 0) + calc = example.calculator.Calculator(5, 0) with pytest.raises(ZeroDivisionError): calc.divide() annotated_logger_mock.assert_logged( @@ -419,9 +418,9 @@ def test_post_call_exception(self, annotated_logger_mock): ) def test_post_call_boom(self, annotated_logger_mock): - calc = Calculator(5, 0) + calc = example.calculator.Calculator(5, 0) calc.boom = True - with pytest.raises(BoomError): + with pytest.raises(example.calculator.BoomError): calc.multiply(1, 2) annotated_logger_mock.assert_logged( "warning", @@ -448,7 +447,7 @@ def test_post_call_boom(self, annotated_logger_mock): ) def test_pre_call_boom(self, annotated_logger_mock): - calc = Calculator(5, 11) + calc = example.calculator.Calculator(5, 11) del calc.second with pytest.raises(AttributeError): calc.divide() @@ -461,73 +460,8 @@ def test_pre_call_boom(self, annotated_logger_mock): }, ) - def test_decorated_class(self, annotated_logger_mock: AnnotatedLogMock): - api = ApiClient() - annotated_logger_mock.assert_logged( - "DEBUG", - "init", - present={ - "class": "example.api:ApiClient", - }, - absent="action", - ) - api.check() - annotated_logger_mock.assert_logged( - "INFO", - "Check passed", - present={ - "class": "example.api:ApiClient", - "action": "example.api:ApiClient.check", - "valid": True, - "lasting": "forever", - }, - ) - api.check_again() - annotated_logger_mock.assert_logged( - "INFO", - "Check passed", - present={ - "class": "example.api:ApiClient", - "action": "example.api:ApiClient.check_again", - "valid": True, - "lasting": "forever", - }, - ) - api.prepare() - annotated_logger_mock.assert_logged( - "INFO", - "Preparation complete", - present={ - "class": "example.api:ApiClient", - "action": "example.api:ApiClient.prepare", - "prepared": True, - "lasting": "forever", - }, - absent=["valid", "args_length"], - ) - - def test_args_splat(self, annotated_logger_mock: AnnotatedLogMock): - default = DefaultExample() - default.var_args("first", "arg0", "first_arg") - annotated_logger_mock.assert_logged( - "info", - "success", - present={"arg0": "arg0", "arg1": "first_arg"}, - count=1, - ) - - def test_kwargs_splat(self, annotated_logger_mock: AnnotatedLogMock): - default = DefaultExample() - default.var_kwargs("first", kwarg1="kwarg1", kwarg2="second_kwarg") - annotated_logger_mock.assert_logged( - "info", - "success", - present={"kwarg1": "kwarg1", "kwarg2": "second_kwarg"}, - count=1, - ) - def test_args_kwargs_splat(self, annotated_logger_mock: AnnotatedLogMock): - default = DefaultExample() + default = example.default.DefaultExample() default.var_args_and_kwargs( "first", "arg0", "first_arg", kwarg1="kwarg1", kwarg2="second_kwarg" ) @@ -544,7 +478,7 @@ def test_args_kwargs_splat(self, annotated_logger_mock: AnnotatedLogMock): ) def test_positional_only(self, annotated_logger_mock: AnnotatedLogMock): - default = DefaultExample() + default = example.default.DefaultExample() default.positional_only("first", _second="second") annotated_logger_mock.assert_logged( "info", @@ -554,7 +488,7 @@ def test_positional_only(self, annotated_logger_mock: AnnotatedLogMock): ) def test_args_kwargs_splat_provided(self, annotated_logger_mock: AnnotatedLogMock): - default = DefaultExample() + default = example.default.DefaultExample() default.var_args_and_kwargs_provided_outer( "first", "arg0", "first_arg", kwarg1="kwarg1", kwarg2="second_kwarg" @@ -573,10 +507,91 @@ def test_args_kwargs_splat_provided(self, annotated_logger_mock: AnnotatedLogMoc count=1, ) + +@pytest.mark.usefixtures("_reload_default") +class TestDefaultExample: + def test_no_annotations(self, annotated_logger_mock): + default = example.default.DefaultExample() + default.foo() + annotated_logger_mock.assert_logged( + "info", + "foo", + absent=annotated_logger_mock.ALL, + count=1, + ) + + def test_args_splat(self, annotated_logger_mock: AnnotatedLogMock): + default = example.default.DefaultExample() + default.var_args("first", "arg0", "first_arg") + annotated_logger_mock.assert_logged( + "info", + "success", + present={"arg0": "arg0", "arg1": "first_arg"}, + count=1, + ) + + def test_kwargs_splat(self, annotated_logger_mock: AnnotatedLogMock): + default = example.default.DefaultExample() + default.var_kwargs("first", kwarg1="kwarg1", kwarg2="second_kwarg") + annotated_logger_mock.assert_logged( + "info", + "success", + present={"kwarg1": "kwarg1", "kwarg2": "second_kwarg"}, + count=1, + ) + + +@pytest.mark.usefixtures("_reload_api") +class TestApiExample: + def test_decorated_class(self, annotated_logger_mock: AnnotatedLogMock): + api = example.api.ApiClient() + annotated_logger_mock.assert_logged( + "DEBUG", + "init", + present={ + "class": "example.api:ApiClient", + }, + absent="action", + ) + api.check() + annotated_logger_mock.assert_logged( + "INFO", + "Check passed", + present={ + "class": "example.api:ApiClient", + "action": "example.api:ApiClient.check", + "valid": True, + "lasting": "forever", + }, + ) + api.check_again() + annotated_logger_mock.assert_logged( + "INFO", + "Check passed", + present={ + "class": "example.api:ApiClient", + "action": "example.api:ApiClient.check_again", + "valid": True, + "lasting": "forever", + }, + ) + api.prepare() + annotated_logger_mock.assert_logged( + "INFO", + "Preparation complete", + present={ + "class": "example.api:ApiClient", + "action": "example.api:ApiClient.prepare", + "prepared": True, + "lasting": "forever", + }, + absent=["valid", "args_length"], + ) + def test_args_kwargs_splat_provided_not_instance( self, annotated_logger_mock: AnnotatedLogMock ): - var_args_and_kwargs_provided_outer( + example.default.var_args_and_kwargs_provided_outer( "first", "arg0", "first_arg", kwarg1="kwarg1", kwarg2="second_kwarg" ) annotated_logger_mock.assert_logged( @@ -593,6 +608,8 @@ def test_args_kwargs_splat_provided_not_instance( count=1, ) + +class TestNonClassBased: def test_annotated_logger_must_be_first(self): with pytest.raises( TypeError, match="^annotated_logger must be the first argument$" diff --git a/test/test_logging_config.py b/test/test_logging_config.py index 21c1ffa..82e62e5 100644 --- a/test/test_logging_config.py +++ b/test/test_logging_config.py @@ -11,6 +11,7 @@ def annotated_logger_object(): return logging.getLogger("annotated_logger.logging_config") +@pytest.mark.usefixtures("_reload_logging_config") class TestLoggingConfig: @pytest.mark.parametrize( "annotated_logger_object", diff --git a/test/test_mocks.py b/test/test_mocks.py index 950b97c..bfba062 100644 --- a/test/test_mocks.py +++ b/test/test_mocks.py @@ -1,4 +1,6 @@ -from example.calculator import Calculator +import pytest + +import example.calculator from example.default import DefaultExample @@ -81,9 +83,10 @@ def wrong_present_for_add_success(expected, missing=None, incorrect=None): ) +@pytest.mark.usefixtures("_reload_calculator") class TestAnnotatedLogMock: def test_assert_logged_message_pass(self, annotated_logger_mock): - calc = Calculator(1, 2) + calc = example.calculator.Calculator(1, 2) calc.add() annotated_logger_mock.assert_logged("debug", "start") annotated_logger_mock.assert_logged( @@ -97,7 +100,7 @@ def test_assert_logged_message_pass(self, annotated_logger_mock): annotated_logger_mock.assert_logged("debug", "success") def test_assert_logged_present_pass(self, annotated_logger_mock): - calc = Calculator(1, 2) + calc = example.calculator.Calculator(1, 2) calc.add() annotated_logger_mock.assert_logged("debug", "start", {"extra": "new data"}) annotated_logger_mock.assert_logged( @@ -115,7 +118,7 @@ def test_assert_logged_present_pass(self, annotated_logger_mock): ) def test_assert_logged_absent_pass(self, annotated_logger_mock): - calc = Calculator(1, 2) + calc = example.calculator.Calculator(1, 2) calc.add() annotated_logger_mock.assert_logged( "debug", "start", absent=["first", "second", "other", "foo", "unused"] @@ -135,7 +138,7 @@ def test_assert_logged_absent_pass(self, annotated_logger_mock): ) def test_assert_logged_present_and_absent_pass(self, annotated_logger_mock): - calc = Calculator(1, 2) + calc = example.calculator.Calculator(1, 2) calc.add() annotated_logger_mock.assert_logged( "debug", @@ -177,7 +180,7 @@ def test_assert_logged_no_logs(self, annotated_logger_mock, fail_mock): ) def test_assert_logged_message_wrong(self, annotated_logger_mock, fail_mock): - calc = Calculator(1, 2) + calc = example.calculator.Calculator(1, 2) calc.add() annotated_logger_mock.assert_logged("debug", "wrong: start") annotated_logger_mock.assert_logged( @@ -205,7 +208,7 @@ def test_assert_logged_message_wrong(self, annotated_logger_mock, fail_mock): assert fail_mock.mock_calls[i].args[0] == errors[i] def test_assert_logged_present_wrong(self, annotated_logger_mock, fail_mock): - calc = Calculator(1, 2) + calc = example.calculator.Calculator(1, 2) calc.add() present_values = [ {"wrong": "key", "also wrong": "missing"}, @@ -245,7 +248,7 @@ def test_all_absent_success(self, annotated_logger_mock): ) def test_all_absent_fail(self, annotated_logger_mock, fail_mock): - calc = Calculator(1, 2) + calc = example.calculator.Calculator(1, 2) calc.add() message = "This message will have 'other' as well as 'first' from the annotation above." @@ -274,7 +277,7 @@ def test_all_absent_fail(self, annotated_logger_mock, fail_mock): ) def test_absent_fail(self, annotated_logger_mock, fail_mock): - calc = Calculator(1, 2) + calc = example.calculator.Calculator(1, 2) calc.add() message = "This message will have 'other' as well as 'first' from the annotation above." @@ -303,7 +306,7 @@ def test_absent_fail(self, annotated_logger_mock, fail_mock): ) def test_count_correct(self, annotated_logger_mock): - calc = Calculator(1, 2) + calc = example.calculator.Calculator(1, 2) calc.factorial(5) annotated_logger_mock.assert_logged( @@ -313,7 +316,7 @@ def test_count_correct(self, annotated_logger_mock): ) def test_count_wrong(self, annotated_logger_mock, fail_mock): - calc = Calculator(1, 2) + calc = example.calculator.Calculator(1, 2) calc.factorial(5) annotated_logger_mock.assert_logged( @@ -328,7 +331,7 @@ def test_count_wrong(self, annotated_logger_mock, fail_mock): ) def test_count_wrong_message(self, annotated_logger_mock, fail_mock): - calc = Calculator(1, 2) + calc = example.calculator.Calculator(1, 2) calc.factorial(5) annotated_logger_mock.assert_logged( @@ -358,7 +361,7 @@ def test_count_wrong_message(self, annotated_logger_mock, fail_mock): ) def test_count_wrong_message_and_count(self, annotated_logger_mock, fail_mock): - calc = Calculator(1, 2) + calc = example.calculator.Calculator(1, 2) calc.factorial(5) annotated_logger_mock.assert_logged( @@ -388,7 +391,7 @@ def test_count_wrong_message_and_count(self, annotated_logger_mock, fail_mock): ) def test_count_wrong_present(self, annotated_logger_mock, fail_mock): - calc = Calculator(1, 2) + calc = example.calculator.Calculator(1, 2) calc.factorial(5) annotated_logger_mock.assert_logged( @@ -421,12 +424,12 @@ def test_count_wrong_present(self, annotated_logger_mock, fail_mock): def test_count_zero_correct(self, annotated_logger_mock): annotated_logger_mock.assert_logged("info", "nope", count=0) - calc = Calculator(7, 2) + calc = example.calculator.Calculator(7, 2) calc.factorial(5) annotated_logger_mock.assert_logged("info", "nope", count=0) def test_count_zero_wrong(self, annotated_logger_mock, fail_mock): - calc = Calculator(7, 2) + calc = example.calculator.Calculator(7, 2) calc.factorial(5) annotated_logger_mock.assert_logged("info", "success", count=0) assert ( @@ -436,13 +439,13 @@ def test_count_zero_wrong(self, annotated_logger_mock, fail_mock): def test_count_zero_any_message(self, annotated_logger_mock): annotated_logger_mock.assert_logged("info", count=0) - calc = Calculator(7, 2) + calc = example.calculator.Calculator(7, 2) calc.factorial(5) annotated_logger_mock.assert_logged("warning", count=0) def test_count_zero_any_level(self, annotated_logger_mock, fail_mock): annotated_logger_mock.assert_logged(count=0) - calc = Calculator(7, 2) + calc = example.calculator.Calculator(7, 2) calc.factorial(5) annotated_logger_mock.assert_logged(count=0) assert ( diff --git a/test/test_plugins.py b/test/test_plugins.py index 1376ab5..7848b4e 100644 --- a/test/test_plugins.py +++ b/test/test_plugins.py @@ -5,6 +5,7 @@ from annotated_logger import AnnotatedAdapter, AnnotatedLogger from annotated_logger.plugins import BasePlugin, RenamerPlugin +from example.actions import ActionsExample from example.api import ApiClient from example.calculator import Calculator @@ -233,3 +234,14 @@ def test_exclude_nested_fields(self, annotated_logger_mock): present={"nested_extra": {"nested_key": {}}}, count=1, ) + + +class TestGitHubActionsPlugin: + def test_logs_normally(self, annotated_logger_mock): + action = ActionsExample() + action.first_step() + + annotated_logger_mock.assert_logged("info", "Step 1 running!") + + def test_logs_actions_annotations(self, annotated_logger_mock, caplog): + pass From 5bdda7527a5984f872e8d83a62c8053b3275e542 Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Thu, 10 Oct 2024 18:10:04 -0400 Subject: [PATCH 15/29] Adding note about merging logging configs --- example/logging_config.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/example/logging_config.py b/example/logging_config.py index 52adb35..6eb72d6 100644 --- a/example/logging_config.py +++ b/example/logging_config.py @@ -30,6 +30,8 @@ # Note: When creating multiple loggers, especially when doing so in different # files/configs keep in mind that names should be unique or they will override # eachother leaving you with a very confusing mess. +# If you want to see how to more easily merge settings into the default logging +# dict this package uses see the `actions.py` example. LOGGING = { "version": 1, "disable_existing_loggers": False, From 47ed59c35d12324f3aaf7eeaaf58fd06e765783b Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Tue, 26 Nov 2024 17:51:42 -0500 Subject: [PATCH 16/29] Removing mutmut from CI as it is not longer working as expected. --- .github/workflows/mutation.yaml | 38 --------------------------------- 1 file changed, 38 deletions(-) delete mode 100644 .github/workflows/mutation.yaml diff --git a/.github/workflows/mutation.yaml b/.github/workflows/mutation.yaml deleted file mode 100644 index 6ae9140..0000000 --- a/.github/workflows/mutation.yaml +++ /dev/null @@ -1,38 +0,0 @@ -name: Mutation Testing - -on: - pull_request: - -permissions: - contents: read - checks: write - -jobs: - mutation-testing: - - runs-on: ubuntu-latest - steps: - - uses: actions/checkout@v4 - - name: Set up Python - uses: actions/setup-python@v5 - with: - python-version: '3.11' - - name: Install dependencies - run: | - python -m pip install hatch - hatch env create dev - - name: Run mutation testing - run: | - set -e - # Run pytest to get coverage so that mutmut can skip non covered lines - hatch run dev:pytest - hatch run dev:mutmut run --CI --no-progress - hatch run dev:mutmut results - hatch run dev:mutmut junitxml > junit.xml - - name: Parse Results - uses: mikepenz/action-junit-report@v4 - if: always() - with: - report_paths: junit.xml - fail_on_failure: true - require_passed_tests: true From b8479197360a248d26c1a594574e3d4ad47bcdce Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Tue, 26 Nov 2024 18:03:56 -0500 Subject: [PATCH 17/29] Minor cleanup --- pyproject.toml | 2 +- requirements.txt | 3 +++ 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/pyproject.toml b/pyproject.toml index 359603a..b8e70d3 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -7,7 +7,7 @@ name = "annotated-logger" dynamic = ["version"] description = "A decorator that logs the start and end of a function as well as providing an optional logger with annotations" readme = "README.md" -license = "" +license = "MIT" requires-python = ">=3.6" authors = [ { name = "Vuln Mgmt Eng", email = "security+vulnmgmteng@github.com" }, diff --git a/requirements.txt b/requirements.txt index 18cb7f8..a929f47 100644 --- a/requirements.txt +++ b/requirements.txt @@ -2,6 +2,7 @@ # This file is autogenerated by hatch-pip-compile with Python 3.10 # # - makefun +# - pychoir # - python-json-logger # - requests # @@ -14,6 +15,8 @@ idna==3.7 # via requests makefun==1.15.2 # via hatch.envs.default +pychoir==0.0.27 + # via hatch.envs.default python-json-logger==2.0.7 # via hatch.envs.default requests==2.32.3 From 24a8ae25a3215d5e0ed55d173ac8395d36d533b1 Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Tue, 26 Nov 2024 18:08:08 -0500 Subject: [PATCH 18/29] Pin coverage action to a sha --- .github/workflows/coverage.yaml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/coverage.yaml b/.github/workflows/coverage.yaml index 7b45ac2..54be849 100644 --- a/.github/workflows/coverage.yaml +++ b/.github/workflows/coverage.yaml @@ -28,7 +28,7 @@ jobs: echo "[run]" >> .coveragerc echo "relative_files = true" >> .coveragerc - name: Python Coverage Comment - uses: py-cov-action/python-coverage-comment-action@v3.28 + uses: py-cov-action/python-coverage-comment-action@b2eb38dd175bf053189b35f738f9207278b00925 with: GITHUB_TOKEN: ${{ github.token }} MERGE_COVERAGE_FILES: true From 200e0b91531913635081f0a20aecd9b70acfb212 Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Tue, 26 Nov 2024 18:20:05 -0500 Subject: [PATCH 19/29] Cleaning up some code scanning issues --- .github/workflows/package-quality-control.yaml | 4 +++- .github/workflows/pyright.yaml | 4 +++- .github/workflows/pytest.yaml | 2 ++ .github/workflows/ruff.yaml | 2 ++ 4 files changed, 10 insertions(+), 2 deletions(-) diff --git a/.github/workflows/package-quality-control.yaml b/.github/workflows/package-quality-control.yaml index 883d8f5..032aacf 100644 --- a/.github/workflows/package-quality-control.yaml +++ b/.github/workflows/package-quality-control.yaml @@ -11,6 +11,8 @@ on: jobs: # Checks that version number has been updated package-quality-control: + permissions: + contents: read runs-on: ubuntu-latest steps: - name: Checkout Current PR Branch @@ -19,7 +21,7 @@ jobs: uses: actions/setup-python@v5 - name: Check for Changed Files id: changed-files - uses: tj-actions/changed-files@v44 + uses: tj-actions/changed-files@635f118699dd888d737c15018cd30aff2e0274f8 with: files: | pyproject.toml diff --git a/.github/workflows/pyright.yaml b/.github/workflows/pyright.yaml index 94f3aae..b464a74 100644 --- a/.github/workflows/pyright.yaml +++ b/.github/workflows/pyright.yaml @@ -5,6 +5,8 @@ on: jobs: pyright: + permissions: + contents: read runs-on: ubuntu-latest steps: @@ -19,4 +21,4 @@ jobs: hatch env create dev - run: echo "$(hatch env find dev)/bin" >> $GITHUB_PATH - name: Run pyright - uses: jakebailey/pyright-action@v2.3.1 + uses: jakebailey/pyright-action@vb5d50e5cde6547546a5c4ac92e416a8c2c1a1dfe diff --git a/.github/workflows/pytest.yaml b/.github/workflows/pytest.yaml index d43046e..4d06752 100644 --- a/.github/workflows/pytest.yaml +++ b/.github/workflows/pytest.yaml @@ -8,6 +8,8 @@ on: jobs: pytest: + permissions: + contents: read runs-on: ${{ matrix.os }} strategy: diff --git a/.github/workflows/ruff.yaml b/.github/workflows/ruff.yaml index 2d61d70..9c1fb85 100644 --- a/.github/workflows/ruff.yaml +++ b/.github/workflows/ruff.yaml @@ -5,6 +5,8 @@ on: jobs: ruff: + permissions: + contents: read runs-on: ubuntu-latest steps: From 23c94f6f7ee24cbc52bbc5b6b7e932026f440da6 Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Wed, 27 Nov 2024 13:25:52 -0500 Subject: [PATCH 20/29] Fixing up workflows --- .github/workflows/build-and-upload.yaml | 11 ----------- .github/workflows/pyright.yaml | 2 +- 2 files changed, 1 insertion(+), 12 deletions(-) diff --git a/.github/workflows/build-and-upload.yaml b/.github/workflows/build-and-upload.yaml index 9c3bab2..a760870 100644 --- a/.github/workflows/build-and-upload.yaml +++ b/.github/workflows/build-and-upload.yaml @@ -38,14 +38,3 @@ jobs: - name: Build Package uses: ./ # Action defined in action.yaml in the root if: steps.changed-files.outputs.any_changed == 'true' - - - name: Setup Octofactory config - uses: jfrog/setup-jfrog-cli@7c95feb32008765e1b4e626b078dfd897c4340ad - if: steps.changed-files.outputs.any_changed == 'true' - env: - JF_ENV_1: ${{ secrets.OCTOFACTORY_SERVER_CONFIG }} - - - name: Upload to Octofactory - if: steps.changed-files.outputs.any_changed == 'true' - run: | - jfrog rt u dist/ logger-decorator-pypi diff --git a/.github/workflows/pyright.yaml b/.github/workflows/pyright.yaml index b464a74..0619996 100644 --- a/.github/workflows/pyright.yaml +++ b/.github/workflows/pyright.yaml @@ -21,4 +21,4 @@ jobs: hatch env create dev - run: echo "$(hatch env find dev)/bin" >> $GITHUB_PATH - name: Run pyright - uses: jakebailey/pyright-action@vb5d50e5cde6547546a5c4ac92e416a8c2c1a1dfe + uses: jakebailey/pyright-action@b5d50e5cde6547546a5c4ac92e416a8c2c1a1dfe From 84a2086b19395fc3601a30ffbbda2c29997e8f59 Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Wed, 27 Nov 2024 15:44:58 -0500 Subject: [PATCH 21/29] Readme and coverage ci updates --- .github/workflows/coverage.yaml | 11 ----------- README.md | 4 ++++ 2 files changed, 4 insertions(+), 11 deletions(-) diff --git a/.github/workflows/coverage.yaml b/.github/workflows/coverage.yaml index 54be849..932ebf0 100644 --- a/.github/workflows/coverage.yaml +++ b/.github/workflows/coverage.yaml @@ -16,17 +16,6 @@ jobs: contents: write actions: read steps: - - uses: actions/checkout@v4 - - - uses: actions/download-artifact@v4 - id: download - with: - pattern: coverage-* - merge-multiple: true - - name: Re-add relative so the action is happy - run: | - echo "[run]" >> .coveragerc - echo "relative_files = true" >> .coveragerc - name: Python Coverage Comment uses: py-cov-action/python-coverage-comment-action@b2eb38dd175bf053189b35f738f9207278b00925 with: diff --git a/README.md b/README.md index 6089307..4e7eb03 100644 --- a/README.md +++ b/README.md @@ -44,3 +44,7 @@ This project is licensed under the terms of the MIT open source license. Please ## Maintainers This project is primarily maintained by `crimsonknave` on behalf of GitHub's Vulnerability Management team as it was initially developed for our internal use. + +## Support + +Reported bugs will be addressed, pull requests are welcome, but there is limited bandwidth for work on new features. From e251cdb3954ce926a7b75154e856eb141ca29877 Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Wed, 27 Nov 2024 16:14:57 -0500 Subject: [PATCH 22/29] Getting the coverage comment to work again --- .github/workflows/pytest.yaml | 27 +++++++++++++++++++++++++++ 1 file changed, 27 insertions(+) diff --git a/.github/workflows/pytest.yaml b/.github/workflows/pytest.yaml index 4d06752..596245a 100644 --- a/.github/workflows/pytest.yaml +++ b/.github/workflows/pytest.yaml @@ -45,6 +45,33 @@ jobs: hatch run dev:pytest env: COVERAGE_FILE: ".coverage.${{ matrix.os }}.${{ matrix.python-version }}" + - name: Store coverage file + uses: actions/upload-artifact@v4 + with: + name: coverage-${{ matrix.os }}-${{ matrix.python-version }} + path: .coverage.${{ matrix.os }}.${{ matrix.python-version }} + include-hidden-files: true + + coverage: + name: Coverage + runs-on: ubuntu-latest + needs: pytest + permissions: + pull-requests: write + contents: write + steps: + - uses: actions/checkout@v4 + - uses: actions/download-artifact@v4 + id: download + with: + pattern: coverage-* + merge-multiple: true + - name: Python Coverage Comment + uses: py-cov-action/python-coverage-comment-action@b2eb38dd175bf053189b35f738f9207278b00925 + with: + GITHUB_TOKEN: ${{ github.token }} + MERGE_COVERAGE_FILES: true + GITHUB_PR_RUN_ID: ${{ github.event.workflow_run.id }} - name: Store Pull Request comment to be posted uses: actions/upload-artifact@v4 if: steps.coverage_comment.outputs.COMMENT_FILE_WRITTEN == 'true' From ba69eff251d3b1f05482e8de6aa40443ceadc414 Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Wed, 27 Nov 2024 16:20:51 -0500 Subject: [PATCH 23/29] Fixing action yaml --- .github/workflows/pytest.yaml | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/.github/workflows/pytest.yaml b/.github/workflows/pytest.yaml index 596245a..096a931 100644 --- a/.github/workflows/pytest.yaml +++ b/.github/workflows/pytest.yaml @@ -46,19 +46,19 @@ jobs: env: COVERAGE_FILE: ".coverage.${{ matrix.os }}.${{ matrix.python-version }}" - name: Store coverage file - uses: actions/upload-artifact@v4 - with: - name: coverage-${{ matrix.os }}-${{ matrix.python-version }} - path: .coverage.${{ matrix.os }}.${{ matrix.python-version }} - include-hidden-files: true + uses: actions/upload-artifact@v4 + with: + name: coverage-${{ matrix.os }}-${{ matrix.python-version }} + path: .coverage.${{ matrix.os }}.${{ matrix.python-version }} + include-hidden-files: true coverage: name: Coverage runs-on: ubuntu-latest needs: pytest - permissions: - pull-requests: write - contents: write + permissions: + pull-requests: write + contents: write steps: - uses: actions/checkout@v4 - uses: actions/download-artifact@v4 From 28ccdc219867850ce8ee42b35e285b9b21b3ad50 Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Wed, 27 Nov 2024 16:31:20 -0500 Subject: [PATCH 24/29] More fixing of CI --- .github/workflows/coverage.yaml | 1 - .github/workflows/pytest.yaml | 1 - 2 files changed, 2 deletions(-) diff --git a/.github/workflows/coverage.yaml b/.github/workflows/coverage.yaml index 932ebf0..14f70e9 100644 --- a/.github/workflows/coverage.yaml +++ b/.github/workflows/coverage.yaml @@ -20,5 +20,4 @@ jobs: uses: py-cov-action/python-coverage-comment-action@b2eb38dd175bf053189b35f738f9207278b00925 with: GITHUB_TOKEN: ${{ github.token }} - MERGE_COVERAGE_FILES: true GITHUB_PR_RUN_ID: ${{ github.event.workflow_run.id }} diff --git a/.github/workflows/pytest.yaml b/.github/workflows/pytest.yaml index 096a931..86dfcf4 100644 --- a/.github/workflows/pytest.yaml +++ b/.github/workflows/pytest.yaml @@ -71,7 +71,6 @@ jobs: with: GITHUB_TOKEN: ${{ github.token }} MERGE_COVERAGE_FILES: true - GITHUB_PR_RUN_ID: ${{ github.event.workflow_run.id }} - name: Store Pull Request comment to be posted uses: actions/upload-artifact@v4 if: steps.coverage_comment.outputs.COMMENT_FILE_WRITTEN == 'true' From 8de95a84562d63d8e27dfbeb1b101e4fbc7522fc Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Wed, 27 Nov 2024 16:38:28 -0500 Subject: [PATCH 25/29] Maybe actually fix the coverage ci --- .github/workflows/pytest.yaml | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/.github/workflows/pytest.yaml b/.github/workflows/pytest.yaml index 86dfcf4..5fe70fa 100644 --- a/.github/workflows/pytest.yaml +++ b/.github/workflows/pytest.yaml @@ -40,7 +40,6 @@ jobs: # Need relative files for the action to report, but it messes up mutmut echo "[run]" >> .coveragerc echo "relative_files = true" >> .coveragerc - cat .coveragerc hatch run dev:pytest env: @@ -66,6 +65,11 @@ jobs: with: pattern: coverage-* merge-multiple: true + - name: Re-add relative so the action is happy + run: | + # Need relative files for the action to report, but it messes up mutmut + echo "[run]" >> .coveragerc + echo "relative_files = true" >> .coveragerc - name: Python Coverage Comment uses: py-cov-action/python-coverage-comment-action@b2eb38dd175bf053189b35f738f9207278b00925 with: From a2f4d6a1270fd9a90a42f269006d90fce13e2588 Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Tue, 3 Dec 2024 17:57:24 -0500 Subject: [PATCH 26/29] Convert runtime annotations to plugin and additional testing for actions plugin --- annotated_logger/__init__.py | 11 ++++++----- annotated_logger/filter.py | 15 +++++---------- annotated_logger/plugins.py | 26 ++++++++++++++++++++++---- example/actions.py | 5 +++++ example/api.py | 8 +++++--- example/calculator.py | 3 ++- example/logging_config.py | 12 +++++++++--- test/test_decorator.py | 15 ++++++++++----- test/test_plugins.py | 13 +++++++++++-- 9 files changed, 75 insertions(+), 33 deletions(-) diff --git a/annotated_logger/__init__.py b/annotated_logger/__init__.py index 82d87ad..6430591 100644 --- a/annotated_logger/__init__.py +++ b/annotated_logger/__init__.py @@ -24,7 +24,7 @@ from makefun import wraps from annotated_logger.filter import AnnotatedFilter -from annotated_logger.plugins import BasePlugin +from annotated_logger.plugins import BasePlugin, RuntimeAnnotationsPlugin if TYPE_CHECKING: # pragma: no cover from collections.abc import MutableMapping @@ -255,8 +255,8 @@ class AnnotatedLogger: Args: ---- annotations: Dictionary of annotations to be added to every log message - runtime_annotations: dictionary of method references to be called when - a log message is emitted + runtime_annotations: [Deprecated] Dictionary of method references to be called + when a log message is emitted. Use the `RuntimeAnnotationsPlugin` instead. plugins: list of plugins to use Methods: @@ -313,9 +313,11 @@ def __init__( # noqa: PLR0913 self.logger_base = logging.getLogger(self.logger_root_name) self.logger_base.setLevel(self.log_level) self.annotations = annotations or {} - self.runtime_annotations = runtime_annotations or {} self.plugins = [BasePlugin()] self.plugins.extend(plugins) + # Preserve the `runtime_annotations` param for backwards compat + if runtime_annotations: + self.plugins.append(RuntimeAnnotationsPlugin(runtime_annotations)) if formatter and config: msg = "Cannot pass both formatter and config." raise ValueError(msg) @@ -385,7 +387,6 @@ def generate_filter( return AnnotatedFilter( annotations=annotations, class_annotations=class_annotations, - runtime_annotations=self.runtime_annotations, plugins=self.plugins, ) diff --git a/annotated_logger/filter.py b/annotated_logger/filter.py index d2c3c2d..02205c9 100644 --- a/annotated_logger/filter.py +++ b/annotated_logger/filter.py @@ -1,6 +1,7 @@ from __future__ import annotations import logging +from copy import copy from typing import Any import annotated_logger @@ -14,14 +15,12 @@ class AnnotatedFilter(logging.Filter): def __init__( self, annotations: Annotations | None = None, - runtime_annotations: Annotations | None = None, class_annotations: Annotations | None = None, plugins: list[annotated_logger.BasePlugin] | None = None, ) -> None: """Store the annotations, attributes and plugins.""" self.annotations = annotations or {} self.class_annotations = class_annotations or {} - self.runtime_annotations = runtime_annotations or {} self.plugins = plugins or [annotated_logger.BasePlugin()] # This allows plugins to determine what fields were added by the user @@ -29,14 +28,10 @@ def __init__( # TODO(crimsonknave): Make a test for this # noqa: TD003, FIX002 self.base_attributes = logging.makeLogRecord({}).__dict__ # pragma: no mutate - def _all_annotations(self, record: logging.LogRecord) -> Annotations: + def _all_annotations(self) -> Annotations: annotations = {} - # Using copy might be better, but, we don't want to add - # the runtime annotations to the stored annotations - annotations.update(self.class_annotations) - annotations.update(self.annotations) - for key, function in self.runtime_annotations.items(): - annotations[key] = function(record) + annotations.update(copy(self.class_annotations)) + annotations.update(copy(self.annotations)) annotations["annotated"] = True return annotations @@ -48,7 +43,7 @@ def filter(self, record: logging.LogRecord) -> bool: sees it. Returning False from the filter method will stop the evaluation and the log record won't be emitted. """ - record.__dict__.update(self._all_annotations(record)) + record.__dict__.update(self._all_annotations()) for plugin in self.plugins: try: result = plugin.filter(record) diff --git a/annotated_logger/plugins.py b/annotated_logger/plugins.py index 461e584..535db25 100644 --- a/annotated_logger/plugins.py +++ b/annotated_logger/plugins.py @@ -2,7 +2,7 @@ import contextlib import logging -from typing import TYPE_CHECKING +from typing import TYPE_CHECKING, Any, Callable from requests.exceptions import HTTPError @@ -23,11 +23,29 @@ def uncaught_exception( self, exception: Exception, logger: AnnotatedAdapter ) -> AnnotatedAdapter: """Handle an uncaught excaption.""" - logger.annotate(success=False) - logger.annotate(exception_title=str(exception)) + if "success" not in logger.filter.annotations: + logger.annotate(success=False) + if "exception_title" not in logger.filter.annotations: + logger.annotate(exception_title=str(exception)) return logger +class RuntimeAnnotationsPlugin(BasePlugin): + """Plugin that sets annotations dynamically.""" + + def __init__( + self, runtime_annotations: dict[str, Callable[[logging.LogRecord], Any]] + ) -> None: + """Store the runtime annotations.""" + self.runtime_annotations = runtime_annotations + + def filter(self, record: logging.LogRecord) -> bool: + """Add any configured runtime annotations.""" + for key, function in self.runtime_annotations.items(): + record.__dict__[key] = function(record) + return True + + class RequestsPlugin(BasePlugin): """Plugin for the requests library.""" @@ -182,7 +200,7 @@ def logging_config(self) -> dict[str, dict[str, object]]: "level": "DEBUG", "handlers": [ # This is from the default logging config - "annotated_handler", + # "annotated_handler", "actions_handler", ], }, diff --git a/example/actions.py b/example/actions.py index 73c57e7..9a581ee 100644 --- a/example/actions.py +++ b/example/actions.py @@ -41,3 +41,8 @@ class ActionsExample: def first_step(self, annotated_logger: AnnotatedAdapter) -> None: """First step of your action.""" annotated_logger.info("Step 1 running!") + + @annotate_logs(_typing_requested=True) + def second_step(self, annotated_logger: AnnotatedAdapter) -> None: + """Second step of your action.""" + annotated_logger.debug("Step 2 running!") diff --git a/example/api.py b/example/api.py index ca0277e..bb1c471 100644 --- a/example/api.py +++ b/example/api.py @@ -7,7 +7,7 @@ from requests.models import Response from annotated_logger import AnnotatedAdapter, AnnotatedLogger -from annotated_logger.plugins import RequestsPlugin +from annotated_logger.plugins import RequestsPlugin, RuntimeAnnotationsPlugin def runtime(_record: logging.LogRecord) -> str: @@ -17,8 +17,10 @@ def runtime(_record: logging.LogRecord) -> str: annotated_logger = AnnotatedLogger( annotations={"extra": "new data"}, - runtime_annotations={"runtime": runtime}, - plugins=[RequestsPlugin()], + plugins=[ + RequestsPlugin(), + RuntimeAnnotationsPlugin({"runtime": runtime}), + ], log_level=logging.DEBUG, name="annotated_logger.api", ) diff --git a/example/calculator.py b/example/calculator.py index f5c9010..bcca52e 100644 --- a/example/calculator.py +++ b/example/calculator.py @@ -7,6 +7,7 @@ NameAdjusterPlugin, NestedRemoverPlugin, RemoverPlugin, + RuntimeAnnotationsPlugin, ) @@ -24,13 +25,13 @@ def runtime(_record: logging.LogRecord) -> str: "extra": "new data", "nested_extra": {"nested_key": {"double_nested_key": "value"}}, }, - runtime_annotations={"runtime": runtime}, log_level=logging.DEBUG, plugins=[ NameAdjusterPlugin(names=["joke"], prefix="cheezy_"), NameAdjusterPlugin(names=["power"], postfix="_overwhelming"), RemoverPlugin("taskName"), NestedRemoverPlugin(["double_nested_key"]), + RuntimeAnnotationsPlugin({"runtime": runtime}), ], name="annotated_logger.calculator", ) diff --git a/example/logging_config.py b/example/logging_config.py index 6eb72d6..fa7dd4b 100644 --- a/example/logging_config.py +++ b/example/logging_config.py @@ -2,7 +2,7 @@ import logging.config from annotated_logger import AnnotatedAdapter, AnnotatedFilter, AnnotatedLogger -from annotated_logger.plugins import BasePlugin, RenamerPlugin +from annotated_logger.plugins import BasePlugin, RenamerPlugin, RuntimeAnnotationsPlugin # This logging config creates 4 loggers: # * A logger for "annotated_logger.logging_config", which logs all messages as json and @@ -48,8 +48,10 @@ "()": AnnotatedFilter, "annotations": {"decorated": False, "class_based_filter": True}, "class_annotations": {}, - "runtime_annotations": {"custom_runtime": lambda _record: True}, - "plugins": [BasePlugin()], + "plugins": [ + BasePlugin(), + RuntimeAnnotationsPlugin({"custom_runtime": lambda _record: True}), + ], }, }, "handlers": { @@ -153,6 +155,10 @@ def runtime(_record: logging.LogRecord) -> str: annotated_logger = AnnotatedLogger( annotations={"hostname": "my-host"}, + # This is deprecated, use the RuntimeAnnotationsPlugin instead. + # This param is kept for backwards compatibility and creates a + # RuntimeAnnotationsPlugin instead. + # This is left as an example and to provide test coverage. runtime_annotations={"runtime": runtime}, plugins=[RenamerPlugin(time="created", lvl="levelname")], log_level=logging.DEBUG, diff --git a/test/test_decorator.py b/test/test_decorator.py index 166854d..523514b 100644 --- a/test/test_decorator.py +++ b/test/test_decorator.py @@ -11,6 +11,7 @@ import example.default import test.demo from annotated_logger import AnnotatedLogger +from annotated_logger.plugins import RuntimeAnnotationsPlugin if TYPE_CHECKING: from annotated_logger.mocks import AnnotatedLogMock @@ -217,10 +218,14 @@ def test_debug(self, annotated_logger_mock): def test_runtime_not_cached(self, annotated_logger_mock, mocker): runtime_mock = mocker.Mock(name="runtime_not_cached") runtime_mock.side_effect = ["first", "second", "third", "fourth"] - runtime_annotations = example.calculator.annotated_logger.runtime_annotations - example.calculator.annotated_logger.runtime_annotations = { - "runtime": runtime_mock - } + plugin = next( + plugin + for plugin in example.calculator.annotated_logger.plugins + if isinstance(plugin, RuntimeAnnotationsPlugin) + ) + + runtime_annotations = plugin.runtime_annotations + plugin.runtime_annotations = {"runtime": runtime_mock} # Need to use full path as that's what's reloaded. The other tests don't need # to as they're not mocking the runtime annotations calc = example.calculator.Calculator(12, 13) @@ -243,7 +248,7 @@ def test_runtime_not_cached(self, annotated_logger_mock, mocker): "runtime": "second", }, ) - example.calculator.annotated_logger.runtime_annotations = runtime_annotations + plugin.runtime_annotations = runtime_annotations def test_raises_type_error_with_too_few_args(self): calc = example.calculator.Calculator(12, 13) diff --git a/test/test_plugins.py b/test/test_plugins.py index 7848b4e..c9706f5 100644 --- a/test/test_plugins.py +++ b/test/test_plugins.py @@ -236,6 +236,7 @@ def test_exclude_nested_fields(self, annotated_logger_mock): ) +@pytest.mark.usefixtures("_reload_actions") class TestGitHubActionsPlugin: def test_logs_normally(self, annotated_logger_mock): action = ActionsExample() @@ -243,5 +244,13 @@ def test_logs_normally(self, annotated_logger_mock): annotated_logger_mock.assert_logged("info", "Step 1 running!") - def test_logs_actions_annotations(self, annotated_logger_mock, caplog): - pass + @pytest.mark.parametrize( + "annotated_logger_object", [logging.getLogger("annotated_logger.actions")] + ) + def test_logs_actions_annotations(self, annotated_logger_mock): + action = ActionsExample() + action.first_step() + action.second_step() + + assert "notice:: Step 1 running!" in annotated_logger_mock.messages[0] + annotated_logger_mock.assert_logged("DEBUG", count=0) From d183d628536b8b319b0fb2262e4fe7f00f094efb Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Wed, 4 Dec 2024 16:40:47 -0500 Subject: [PATCH 27/29] Cleanup and removing some support for older configurations --- .github/workflows/pytest.yaml | 12 ++---------- SUPPORT.md | 2 +- annotated_logger/__init__.py | 15 +-------------- example/invalid_order.py | 3 +-- example/logging_config.py | 6 ++++-- notes.md | 10 ---------- test/demo.py | 3 ++- test/test_decorator.py | 9 --------- 8 files changed, 11 insertions(+), 49 deletions(-) delete mode 100644 notes.md diff --git a/.github/workflows/pytest.yaml b/.github/workflows/pytest.yaml index 5fe70fa..981b51e 100644 --- a/.github/workflows/pytest.yaml +++ b/.github/workflows/pytest.yaml @@ -14,16 +14,8 @@ jobs: runs-on: ${{ matrix.os }} strategy: matrix: - # pytest-forked does not work on windows and we currently use it for isolation - # of logging configs as logging.dictConfig has a setting to not disable old loggers - # but, does seem to trample old handlers, filters and formatters - os: [ubuntu-latest, macos-latest] - python-version: ["3.9", "3.10", "3.11", "3.12", "pypy3.9", "pypy3.10"] - exclude: - - os: macos-latest - python-version: "3.9" - - os: windows-latest - python-version: "3.9" + os: [ubuntu-latest, macos-latest, windows-latest] + python-version: ["3.9", "3.10", "3.11", "3.12", "3.13"] steps: - uses: actions/checkout@v4 diff --git a/SUPPORT.md b/SUPPORT.md index 45f5139..7f18213 100644 --- a/SUPPORT.md +++ b/SUPPORT.md @@ -6,7 +6,7 @@ This project uses GitHub issues to track bugs and feature requests. Please searc For help or questions about using this project, please create an issue or discussion. -- Annotated Logger is under active development and maintained by GitHub staff **AND THE COMMUNITY**. We will do our best to respond to support, feature requests, and community questions in a timely manner. +Annotated Logger is under active development and maintained by GitHub staff **AND THE COMMUNITY**. We will do our best to respond to support, feature requests, and community questions in a timely manner. ## GitHub Support Policy diff --git a/annotated_logger/__init__.py b/annotated_logger/__init__.py index 6430591..49ca0f6 100644 --- a/annotated_logger/__init__.py +++ b/annotated_logger/__init__.py @@ -24,7 +24,7 @@ from makefun import wraps from annotated_logger.filter import AnnotatedFilter -from annotated_logger.plugins import BasePlugin, RuntimeAnnotationsPlugin +from annotated_logger.plugins import BasePlugin if TYPE_CHECKING: # pragma: no cover from collections.abc import MutableMapping @@ -255,8 +255,6 @@ class AnnotatedLogger: Args: ---- annotations: Dictionary of annotations to be added to every log message - runtime_annotations: [Deprecated] Dictionary of method references to be called - when a log message is emitted. Use the `RuntimeAnnotationsPlugin` instead. plugins: list of plugins to use Methods: @@ -271,10 +269,7 @@ class AnnotatedLogger: def __init__( # noqa: PLR0913 self, annotations: dict[str, Any] | None = None, - runtime_annotations: dict[str, Callable[[logging.LogRecord], Any]] - | None = None, plugins: list[BasePlugin] | None = None, - formatter: logging.Formatter | None = None, max_length: int | None = None, log_level: int = logging.INFO, name: str = "annotated_logger", @@ -285,9 +280,7 @@ def __init__( # noqa: PLR0913 Args: ---- annotations: Dictionary of static annotations - default None - runtime_annotations: Dictionary of dynamic annotations - default None plugins: List of plugins to be applied - default [BasePlugin] - formatter: Formatter for the handler. If none is provided a JsonFormatter is created and used - default None max_length: Integer, maximum length of a message before it's broken into multiple message and log calls. - default None @@ -315,12 +308,6 @@ def __init__( # noqa: PLR0913 self.annotations = annotations or {} self.plugins = [BasePlugin()] self.plugins.extend(plugins) - # Preserve the `runtime_annotations` param for backwards compat - if runtime_annotations: - self.plugins.append(RuntimeAnnotationsPlugin(runtime_annotations)) - if formatter and config: - msg = "Cannot pass both formatter and config." - raise ValueError(msg) if config is None: config = deepcopy(DEFAULT_LOGGING_CONFIG) diff --git a/example/invalid_order.py b/example/invalid_order.py index b38661a..0d487c9 100644 --- a/example/invalid_order.py +++ b/example/invalid_order.py @@ -1,9 +1,8 @@ from annotated_logger import AnnotatedAdapter, AnnotatedLogger -from annotated_logger.plugins import RemoverPlugin # Actions runs in async.io it appears and that inejcts `taskName` # But, locally that's not there, so it messes up the absent all tests -annotated_logger = AnnotatedLogger(plugins=[RemoverPlugin(["taskName"])]) +annotated_logger = AnnotatedLogger() annotate_logs = annotated_logger.annotate_logs diff --git a/example/logging_config.py b/example/logging_config.py index fa7dd4b..7543078 100644 --- a/example/logging_config.py +++ b/example/logging_config.py @@ -159,8 +159,10 @@ def runtime(_record: logging.LogRecord) -> str: # This param is kept for backwards compatibility and creates a # RuntimeAnnotationsPlugin instead. # This is left as an example and to provide test coverage. - runtime_annotations={"runtime": runtime}, - plugins=[RenamerPlugin(time="created", lvl="levelname")], + plugins=[ + RenamerPlugin(time="created", lvl="levelname"), + RuntimeAnnotationsPlugin({"runtime": runtime}), + ], log_level=logging.DEBUG, max_length=200, name="annotated_logger.logging_config", diff --git a/notes.md b/notes.md deleted file mode 100644 index d582b6f..0000000 --- a/notes.md +++ /dev/null @@ -1,10 +0,0 @@ -Should support the ability to configure via a logging config. - -The AnnotatedLogger class would take params that let it build/override parts of the config. - -Need to sort out how we do the mock on the handler then. Have the mock fixture pull in a fixture for what handler to do and then if you don't do that you can override that fixture? How does it work with multiple handlers? - - -The overall goal is to be able to support the case where you want to configure multiple output streams (handlers) with different filters. AKA, output with a different log level that filters/formats for actions notifications at the same time as a normal logger - -Also, move base_attribute support into the plugin base and also store the values we add in the annotated (annotated, action and so on). Then make a function that lets a plugin ask for the bits of a record that were added by the caller or the caller and the annotated_logger. diff --git a/test/demo.py b/test/demo.py index 226365d..7a72f42 100644 --- a/test/demo.py +++ b/test/demo.py @@ -1,6 +1,7 @@ import logging from annotated_logger import AnnotatedLogger +from annotated_logger.plugins import RuntimeAnnotationsPlugin def runtime(_record: logging.LogRecord): @@ -9,7 +10,7 @@ def runtime(_record: logging.LogRecord): annotated_logger = AnnotatedLogger( annotations={"extra": "new data"}, - runtime_annotations={"runtime": runtime}, + plugins=[RuntimeAnnotationsPlugin({"runtime": runtime})], ) annotate_logs = annotated_logger.annotate_logs diff --git a/test/test_decorator.py b/test/test_decorator.py index 523514b..fcceef3 100644 --- a/test/test_decorator.py +++ b/test/test_decorator.py @@ -1,6 +1,5 @@ from __future__ import annotations -import logging from typing import TYPE_CHECKING import pytest @@ -10,7 +9,6 @@ import example.calculator import example.default import test.demo -from annotated_logger import AnnotatedLogger from annotated_logger.plugins import RuntimeAnnotationsPlugin if TYPE_CHECKING: @@ -620,10 +618,3 @@ def test_annotated_logger_must_be_first(self): TypeError, match="^annotated_logger must be the first argument$" ): import example.invalid_order # noqa: F401 - - def test_cannot_use_both_formatter_and_config(self): - formatter = logging.Formatter("%(time)s %(lvl)s %(name)s %(message)s") - with pytest.raises( - ValueError, match="^Cannot pass both formatter and config.$" - ): - AnnotatedLogger(formatter=formatter, config={"logging": "config"}) From 10ea0dd67f1c532b1e060f7b4d3ea693045e9623 Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Wed, 4 Dec 2024 16:53:16 -0500 Subject: [PATCH 28/29] Fully test actions log message --- test/test_plugins.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/test/test_plugins.py b/test/test_plugins.py index c9706f5..234bf66 100644 --- a/test/test_plugins.py +++ b/test/test_plugins.py @@ -252,5 +252,8 @@ def test_logs_actions_annotations(self, annotated_logger_mock): action.first_step() action.second_step() - assert "notice:: Step 1 running!" in annotated_logger_mock.messages[0] + assert ( + "notice:: Step 1 running! - {'action': 'example.actions:ActionsExample.first_step'}" + in annotated_logger_mock.messages[0] + ) annotated_logger_mock.assert_logged("DEBUG", count=0) From 6209b3ac66af3925799c10f676c92789e1cd8f10 Mon Sep 17 00:00:00 2001 From: crimsonknave Date: Wed, 4 Dec 2024 17:48:06 -0500 Subject: [PATCH 29/29] More cleanup --- annotated_logger/plugins.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/annotated_logger/plugins.py b/annotated_logger/plugins.py index 535db25..aaeec06 100644 --- a/annotated_logger/plugins.py +++ b/annotated_logger/plugins.py @@ -162,11 +162,11 @@ def filter(self, record: logging.LogRecord) -> bool: for k, v in record.__dict__.items() if k not in self.base_attributes and k not in self.attributes_to_exclude } - record.__dict__["added_attributes"] = added_attributes + record.added_attributes = added_attributes name = record.levelname.lower() if name == "info": # pragma: no cover name = "notice" - record.__dict__["github_annotation"] = f"{name}::" + record.github_annotation = f"{name}::" return True