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/coverage.yaml b/.github/workflows/coverage.yaml new file mode 100644 index 0000000..14f70e9 --- /dev/null +++ b/.github/workflows/coverage.yaml @@ -0,0 +1,23 @@ + +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: + - name: Python Coverage Comment + uses: py-cov-action/python-coverage-comment-action@b2eb38dd175bf053189b35f738f9207278b00925 + with: + GITHUB_TOKEN: ${{ github.token }} + GITHUB_PR_RUN_ID: ${{ github.event.workflow_run.id }} 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/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 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..0619996 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@b5d50e5cde6547546a5c4ac92e416a8c2c1a1dfe diff --git a/.github/workflows/pytest.yaml b/.github/workflows/pytest.yaml index e9fabfb..981b51e 100644 --- a/.github/workflows/pytest.yaml +++ b/.github/workflows/pytest.yaml @@ -8,17 +8,14 @@ on: jobs: pytest: + permissions: + contents: read runs-on: ${{ matrix.os }} strategy: matrix: os: [ubuntu-latest, macos-latest, windows-latest] - python-version: ["3.9", "3.10", "3.11", "pypy3.9", "pypy3.10"] - exclude: - - os: macos-latest - python-version: "3.9" - - os: windows-latest - python-version: "3.9" + python-version: ["3.9", "3.10", "3.11", "3.12", "3.13"] steps: - uses: actions/checkout@v4 @@ -35,7 +32,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: @@ -45,8 +41,10 @@ jobs: 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: @@ -54,7 +52,6 @@ jobs: contents: write steps: - uses: actions/checkout@v4 - - uses: actions/download-artifact@v4 id: download with: @@ -62,10 +59,18 @@ jobs: 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@v3.24 + uses: py-cov-action/python-coverage-comment-action@b2eb38dd175bf053189b35f738f9207278b00925 with: GITHUB_TOKEN: ${{ github.token }} MERGE_COVERAGE_FILES: true + - 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 + include-hidden-files: true diff --git a/.github/workflows/ruff.yaml b/.github/workflows/ruff.yaml index 54d3a36..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: @@ -17,6 +19,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/.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/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/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. diff --git a/README.md b/README.md index 45422a3..4e7eb03 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,13 @@ 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. +## 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. -`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. +## Support -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. +Reported bugs will be addressed, pull requests are welcome, but there is limited bandwidth for work on new features. 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..7f18213 --- /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. diff --git a/annotated_logger/__init__.py b/annotated_logger/__init__.py index 213bd26..49ca0f6 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,14 +22,14 @@ ) from makefun import wraps -from pythonjsonlogger.jsonlogger import JsonFormatter +from annotated_logger.filter import AnnotatedFilter from annotated_logger.plugins import BasePlugin 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") @@ -88,7 +88,35 @@ class AnnotatedClass(Protocol[C_co]): Annotations = dict[str, Any] -handler = logging.StreamHandler(sys.stdout) +DEFAULT_LOGGING_CONFIG = { + "version": 1, + "disable_existing_loggers": False, # pragma: no mutate + "filters": { + "annotated_filter": { + "annotated_filter": True, # pragma: no mutate + } + }, + "handlers": { + "annotated_handler": { + "class": "logging.StreamHandler", + "formatter": "annotated_formatter", + }, + }, + "formatters": { + "annotated_formatter": { + "class": "pythonjsonlogger.jsonlogger.JsonFormatter", # pragma: no mutate + "format": "{created} {levelname} {name} {message}", # pragma: no mutate + "style": "{", + }, + }, + "loggers": { + "annotated_logger": { + "level": "DEBUG", + "handlers": ["annotated_handler"], + "propagate": False, # pragma: no mutate + }, + }, +} class AnnotatedIterator(Iterator[T]): @@ -136,62 +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.""" @@ -283,8 +255,6 @@ 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 plugins: list of plugins to use Methods: @@ -299,22 +269,18 @@ 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", + config: dict[str, Any] | Literal[False] | None = None, ) -> None: """Store the settings. 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 @@ -324,6 +290,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: @@ -334,17 +306,31 @@ 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) - self.formatter = formatter or JsonFormatter( - "%(created)s %(levelname)s %(name)s %(message)s" # pragma: no mutate - ) - handler.setFormatter(self.formatter) + + 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. @@ -352,12 +338,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 ) - logger.addHandler(handler) - annotated_filter = self.generate_filter(function=function, cls=cls) return AnnotatedAdapter(logger, annotated_filter, self.max_length) @@ -368,23 +353,27 @@ 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, - runtime_annotations=self.runtime_annotations, plugins=self.plugins, ) @@ -392,56 +381,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, @@ -453,6 +446,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, @@ -464,6 +458,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, @@ -475,6 +470,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, @@ -484,10 +480,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, @@ -498,6 +507,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, @@ -509,6 +519,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, @@ -520,6 +531,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, @@ -533,6 +545,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, @@ -543,6 +556,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, @@ -554,6 +568,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, @@ -565,6 +580,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, @@ -580,6 +596,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, @@ -591,6 +608,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, @@ -604,6 +622,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, @@ -617,9 +636,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], @@ -630,6 +651,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, @@ -643,6 +665,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 @@ -699,7 +723,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 @@ -721,7 +747,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() @@ -764,7 +790,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[ @@ -788,10 +817,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 @@ -811,6 +844,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( @@ -818,6 +852,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 @@ -831,6 +866,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"] @@ -838,13 +874,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, @@ -852,6 +890,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] @@ -859,7 +898,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 @@ -879,7 +920,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"): @@ -896,7 +940,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/filter.py b/annotated_logger/filter.py new file mode 100644 index 0000000..02205c9 --- /dev/null +++ b/annotated_logger/filter.py @@ -0,0 +1,58 @@ +from __future__ import annotations + +import logging +from copy import copy +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, + 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.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) -> Annotations: + annotations = {} + annotations.update(copy(self.class_annotations)) + annotations.update(copy(self.annotations)) + 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()) + 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/mocks.py b/annotated_logger/mocks.py index bed9ec1..93f80a8 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.""" @@ -111,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, @@ -165,7 +156,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,10 +235,19 @@ def assert_logged( @pytest.fixture() -def annotated_logger_mock(mocker: MagicMock) -> 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.""" - 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..aaeec06 100644 --- a/annotated_logger/plugins.py +++ b/annotated_logger/plugins.py @@ -1,13 +1,14 @@ from __future__ import annotations import contextlib -from typing import TYPE_CHECKING +import logging +from typing import TYPE_CHECKING, Any, Callable 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 @@ -22,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.""" @@ -43,15 +62,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 @@ -115,3 +141,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.added_attributes = added_attributes + name = record.levelname.lower() + if name == "info": # pragma: no cover + name = "notice" + record.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..9a581ee --- /dev/null +++ b/example/actions.py @@ -0,0 +1,48 @@ +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!") + + @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 df0b7c7..bcca52e 100644 --- a/example/calculator.py +++ b/example/calculator.py @@ -7,6 +7,7 @@ NameAdjusterPlugin, NestedRemoverPlugin, RemoverPlugin, + RuntimeAnnotationsPlugin, ) @@ -24,15 +25,15 @@ 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.example", + name="annotated_logger.calculator", ) annotate_logs = annotated_logger.annotate_logs 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/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 f11c19f..7543078 100644 --- a/example/logging_config.py +++ b/example/logging_config.py @@ -1,10 +1,151 @@ import logging import logging.config -from pythonjsonlogger.jsonlogger import JsonFormatter - -from annotated_logger import AnnotatedAdapter, AnnotatedLogger -from annotated_logger.plugins import RenamerPlugin +from annotated_logger import AnnotatedAdapter, AnnotatedFilter, AnnotatedLogger +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 +# 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. +# 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, + "filters": { + "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": {"config_based_filter": True}, + }, + "logging_config.logger_filter_parens": { + "()": AnnotatedFilter, + "annotations": {"decorated": False, "class_based_filter": True}, + "class_annotations": {}, + "plugins": [ + BasePlugin(), + RuntimeAnnotationsPlugin({"custom_runtime": lambda _record: True}), + ], + }, + }, + "handlers": { + "logging_config.annotated_handler": { + "class": "logging.StreamHandler", + "formatter": "logging_config.annotated_formatter", + }, + "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", + ], + "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", + "formatter": "logging_config.weird_formatter", + }, + }, + "formatters": { + "logging_config.annotated_formatter": { + "class": "pythonjsonlogger.jsonlogger.JsonFormatter", + # 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": "{", + }, + "logging_config.error_formatter": { + "format": "{level} {message}", + "style": "{", + }, + "logging_config.long_formatter": { + "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 + # 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": { + "annotated_logger.logging_config": { + "level": "DEBUG", + "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, + }, + }, +} def runtime(_record: logging.LogRecord) -> str: @@ -13,63 +154,32 @@ def runtime(_record: logging.LogRecord) -> str: 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"), + 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. + plugins=[ + RenamerPlugin(time="created", lvl="levelname"), + RuntimeAnnotationsPlugin({"runtime": runtime}), + ], 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")], - formatter=JsonFormatter("%(time)s %(lvl)s %(name)s %(message)s"), - log_level=logging.DEBUG, - name="annotated_logger.weird_logging_config", + log_level=logging.INFO, + name="annotated_logger.logging_config_weird", + config=False, ) 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 -LOGGING = { - "version": 1, - "filters": { - "annotated_filter": { - "()": annotated_logger.generate_filter, - "function": None, - } - }, - "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": "{time} {level} {module} {extra} {runtime} {message}", - "style": "{", - }, - }, - "loggers": { - "demo": { - "level": "DEBUG", - "handlers": ["annotated_handler"], - }, - }, -} - - -logging.config.dictConfig(LOGGING) -logger = logging.getLogger("demo") +logger = logging.getLogger("annotated_logger.logging_config.logger") logger.setLevel("DEBUG") @@ -90,7 +200,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 +212,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..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" }, @@ -64,6 +64,7 @@ dependencies = [ "pytest-freezer", "pytest-github-actions-annotate-failures", "pytest-mock", + "pytest-randomly", "requests-mock", "ruff", "typing_extensions", @@ -91,7 +92,7 @@ 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 addopts = "--cov=annotated_logger --cov=example --cov-report html --cov-report term -p no:annotated_logger" filterwarnings = [ 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 diff --git a/requirements/requirements-dev.txt b/requirements/requirements-dev.txt index ad30a36..20f5548 100644 --- a/requirements/requirements-dev.txt +++ b/requirements/requirements-dev.txt @@ -10,11 +10,12 @@ # - pytest-freezer # - pytest-github-actions-annotate-failures # - pytest-mock +# - pytest-randomly # - requests-mock # - ruff # - typing_extensions -# - pychoir # - makefun +# - pychoir # - python-json-logger # - requests # @@ -80,6 +81,7 @@ pytest==8.2.2 # pytest-freezer # pytest-github-actions-annotate-failures # pytest-mock + # pytest-randomly pytest-cov==5.0.0 # via hatch.envs.dev pytest-freezer==0.4.8 @@ -88,6 +90,8 @@ 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/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 cb9abc8..fcceef3 100644 --- a/test/test_decorator.py +++ b/test/test_decorator.py @@ -1,18 +1,25 @@ +from __future__ import annotations + +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.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 +from annotated_logger.plugins import RuntimeAnnotationsPlugin + +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() @@ -30,7 +37,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", @@ -47,7 +54,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", @@ -81,7 +88,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( @@ -121,7 +128,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( @@ -150,7 +157,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( @@ -165,7 +172,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", @@ -181,7 +188,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!", @@ -194,7 +201,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", @@ -209,9 +216,17 @@ 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) + 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) calc.subtract() annotated_logger_mock.assert_logged( "DEBUG", @@ -231,15 +246,15 @@ def test_runtime_not_cached(self, annotated_logger_mock, mocker): "runtime": "second", }, ) - annotated_logger.runtime_annotations = runtime_annotations + plugin.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$", @@ -253,7 +268,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", @@ -270,7 +285,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", @@ -285,7 +300,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() @@ -313,7 +328,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]: @@ -332,7 +347,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 @@ -349,22 +364,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() @@ -376,7 +381,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"] ) @@ -390,14 +395,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", @@ -406,7 +411,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( @@ -416,9 +421,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", @@ -445,7 +450,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() @@ -458,73 +463,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" ) @@ -541,7 +481,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", @@ -551,7 +491,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" @@ -570,10 +510,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( @@ -590,6 +611,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 e7d9bfe..82e62e5 100644 --- a/test/test_logging_config.py +++ b/test/test_logging_config.py @@ -1,32 +1,36 @@ +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") + + +@pytest.mark.usefixtures("_reload_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={ + "decorated": False, + "config_based_filter": True, + "class_based_filter": True, + "lvl": level.upper(), + }, + absent=["weird", "hostname"], + ) def test_annotated_logging(self, annotated_logger_mock: AnnotatedLogMock): example.logging_config.make_some_annotated_logs() @@ -34,7 +38,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 +47,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 +66,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 +77,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 +86,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 +95,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 +121,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 +134,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 +147,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 +157,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 +170,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 +183,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_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 f3a4533..234bf66 100644 --- a/test/test_plugins.py +++ b/test/test_plugins.py @@ -4,7 +4,8 @@ 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.actions import ActionsExample from example.api import ApiClient from example.calculator import Calculator @@ -40,6 +41,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 +74,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 +103,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 +114,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 +193,36 @@ 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(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, match="'LogRecord' object has no attribute 'failed_plugins'" + ): + _ = record.failed_plugins + class TestNestedRemoverPlugin: def test_exclude_nested_fields(self, annotated_logger_mock): @@ -188,3 +234,26 @@ def test_exclude_nested_fields(self, annotated_logger_mock): present={"nested_extra": {"nested_key": {}}}, count=1, ) + + +@pytest.mark.usefixtures("_reload_actions") +class TestGitHubActionsPlugin: + def test_logs_normally(self, annotated_logger_mock): + action = ActionsExample() + action.first_step() + + annotated_logger_mock.assert_logged("info", "Step 1 running!") + + @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! - {'action': 'example.actions:ActionsExample.first_step'}" + in annotated_logger_mock.messages[0] + ) + annotated_logger_mock.assert_logged("DEBUG", count=0)