diff --git a/.changesets/apply-the-log-level-set-with-basic-config.md b/.changesets/apply-the-log-level-set-with-basic-config.md new file mode 100644 index 00000000..ebb1bf44 --- /dev/null +++ b/.changesets/apply-the-log-level-set-with-basic-config.md @@ -0,0 +1,6 @@ +--- +bump: patch +type: fix +--- + +`logging.basicConfig()` applies the log level it is given. An application that calls it with a level below `WARNING`, such as `logging.INFO`, starts sending its log lines at that level. diff --git a/.changesets/keep-internal-logs-out-of-your-logs.md b/.changesets/keep-internal-logs-out-of-your-logs.md new file mode 100644 index 00000000..59bf3eb4 --- /dev/null +++ b/.changesets/keep-internal-logs-out-of-your-logs.md @@ -0,0 +1,6 @@ +--- +bump: patch +type: fix +--- + +When `disable_default_instrumentations` is used to disable the `logging` instrumentation, prevent the log lines emitted internally by AppSignal from propagating to a manually configured OpenTelemetry handler in the root logger. diff --git a/.changesets/keep-sending-logs-when-logging-is-configured.md b/.changesets/keep-sending-logs-when-logging-is-configured.md new file mode 100644 index 00000000..1624baef --- /dev/null +++ b/.changesets/keep-sending-logs-when-logging-is-configured.md @@ -0,0 +1,8 @@ +--- +bump: patch +type: fix +--- + +Logs are now still sent after your application configures the logging module. `logging.config.dictConfig()`, `logging.config.fileConfig()` and `logging.basicConfig()` keep AppSignal's log handler attached, so a configuration that sets its own handlers on the root logger, such as Django's `LOGGING` setting, will now send its logs to AppSignal as well. + +If you have manually added an OpenTelemetry log handler to your `LOGGING` setting or to the root logger elsewhere, it should now be removed, as AppSignal's handler will now send those log lines as well, causing them to be sent twice. AppSignal will log a warning when it detects a redundant OpenTelemetry handler. \ No newline at end of file diff --git a/.changesets/require-python-3-10.md b/.changesets/require-python-3-10.md new file mode 100644 index 00000000..67e8eb65 --- /dev/null +++ b/.changesets/require-python-3-10.md @@ -0,0 +1,6 @@ +--- +bump: minor +type: remove +--- + +AppSignal for Python no longer supports Python 3.8 and 3.9, requiring Python 3.10 or newer. \ No newline at end of file diff --git a/.changesets/send-a-non-string-log-message-as-text.md b/.changesets/send-a-non-string-log-message-as-text.md new file mode 100644 index 00000000..a3f3515d --- /dev/null +++ b/.changesets/send-a-non-string-log-message-as-text.md @@ -0,0 +1,12 @@ +--- +bump: minor +type: change +--- + +A log message that is not a string, such as the dictionary in `logger.info({"message": "Order placed", "order_id": 1234})`, is sent as text by the `logging` instrumentation. Pass the structured values in the `extra` argument to send a structured log line: + +```python +logger.info("Order placed", extra={"order_id": 1234}) +``` + +[The OpenTelemetry logs API](https://docs.appsignal.com/logging/integrations/python#sending-logs-with-opentelemetry) sends a structured log line from a dictionary body. diff --git a/.changesets/send-one-log-line-per-forked-process.md b/.changesets/send-one-log-line-per-forked-process.md new file mode 100644 index 00000000..137b2ffc --- /dev/null +++ b/.changesets/send-one-log-line-per-forked-process.md @@ -0,0 +1,6 @@ +--- +bump: patch +type: fix +--- + +Fix an issue where AppSignal would configure redundant handlers when starting again in a forked process, such as when a Celery worker calls `appsignal.start()` from the `worker_process_init` signal. \ No newline at end of file diff --git a/.changesets/warn-about-the-deprecated-log-handler.md b/.changesets/warn-about-the-deprecated-log-handler.md new file mode 100644 index 00000000..8ce5918c --- /dev/null +++ b/.changesets/warn-about-the-deprecated-log-handler.md @@ -0,0 +1,6 @@ +--- +bump: patch +type: add +--- + +AppSignal warns when your application attaches the OpenTelemetry log handler from `opentelemetry.sdk._logs`, which is deprecated and is removed in a future release of the OpenTelemetry SDK. Its replacement is in `opentelemetry.instrumentation.logging.handler`. diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index eeb0ffa7..b3bf0b4f 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -18,7 +18,7 @@ jobs: strategy: fail-fast: false matrix: - python-version: ["3.8", "3.9", "3.10", "3.11", "3.12"] + python-version: ["3.10", "3.11", "3.12", "3.13", "3.14"] steps: - uses: actions/checkout@v4 - uses: actions/setup-python@v5 diff --git a/.python-version b/.python-version index 214a1ad9..4073fcda 100644 --- a/.python-version +++ b/.python-version @@ -1,5 +1,5 @@ +3.14.3 +3.13.12 3.12.2 3.11.3 3.10.11 -3.9.16 -3.8.16 diff --git a/conftest.py b/conftest.py index 69629b1c..d1a1deb0 100644 --- a/conftest.py +++ b/conftest.py @@ -1,14 +1,23 @@ from __future__ import annotations +import logging +import logging.config import os import platform import tempfile import threading +from collections.abc import Callable, Generator from http.server import BaseHTTPRequestHandler, ThreadingHTTPServer -from typing import Any, Callable, Generator +from typing import Any import pytest +from opentelemetry._logs import LogRecord, set_logger_provider from opentelemetry.metrics import set_meter_provider +from opentelemetry.sdk._logs import LoggerProvider +from opentelemetry.sdk._logs.export import ( + InMemoryLogRecordExporter, + SimpleLogRecordProcessor, +) from opentelemetry.sdk.metrics import MeterProvider from opentelemetry.sdk.metrics.export import InMemoryMetricReader from opentelemetry.sdk.resources import Resource @@ -137,6 +146,78 @@ def get_and_clear_spans() -> tuple[ReadableSpan, ...]: yield get_and_clear_spans +@pytest.fixture(scope="session", autouse=True) +def start_in_memory_log_record_exporter() -> ( + Generator[InMemoryLogRecordExporter, None, None] +): + log_record_exporter = InMemoryLogRecordExporter() + provider = LoggerProvider() + provider.add_log_record_processor(SimpleLogRecordProcessor(log_record_exporter)) + set_logger_provider(provider) + + yield log_record_exporter + + +@pytest.fixture(scope="function") +def log_records( + start_in_memory_log_record_exporter: InMemoryLogRecordExporter, +) -> Generator[Callable[[], tuple[LogRecord, ...]], None, None]: + start_in_memory_log_record_exporter.clear() + + def get_and_clear_log_records() -> tuple[LogRecord, ...]: + log_records = tuple( + log_record.log_record + for log_record in start_in_memory_log_record_exporter.get_finished_logs() + ) + start_in_memory_log_record_exporter.clear() + return log_records + + yield get_and_clear_log_records + + +# Starting logging attaches a handler to the root logger, wraps the functions +# that configure the logging module, stops the internal loggers propagating +# and marks the instrumentation as installed. All of that lives on the logging +# module, so it outlives the test that started it and is put back here. +@pytest.fixture(scope="function", autouse=True) +def reset_logging_instrumentation() -> Any: + configure_functions = ( + logging.basicConfig, + logging.config.dictConfig, + logging.config.fileConfig, + ) + propagate = { + name: logging.getLogger(name).propagate + for name in ["appsignal", "opentelemetry"] + } + + yield + + from opentelemetry.instrumentation.logging import LoggingInstrumentor + + instrumentor = LoggingInstrumentor() + if instrumentor.is_instrumented_by_opentelemetry: + instrumentor.uninstrument() + + ( + logging.basicConfig, + logging.config.dictConfig, + logging.config.fileConfig, + ) = configure_functions + + for name, propagates in propagate.items(): + logging.getLogger(name).propagate = propagates + + from appsignal.opentelemetry import _warned_logger_names + + _warned_logger_names.clear() + + for name in ["duplicate", "duplicate_not_propagating", "duplicate_elsewhere"]: + logger = logging.getLogger(name) + logger.handlers.clear() + logger.propagate = True + + @pytest.fixture(scope="function", autouse=True) def reset_environment_between_tests() -> Any: old_environ = dict(os.environ) diff --git a/pyproject.toml b/pyproject.toml index bb2cdc27..686c41b9 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -6,7 +6,7 @@ build-backend = "hatchling.build" name = "appsignal" description = 'The AppSignal integration for the Python programming language' readme = "README.md" -requires-python = ">=3.8" +requires-python = ">=3.10" keywords = [] authors = [ { name = "Tom de Bruijn", email = "tom@tomdebruijn.com" }, @@ -15,20 +15,21 @@ authors = [ classifiers = [ # Python versions "Programming Language :: Python", - "Programming Language :: Python :: 3.8", - "Programming Language :: Python :: 3.9", "Programming Language :: Python :: 3.10", "Programming Language :: Python :: 3.11", "Programming Language :: Python :: 3.12", + "Programming Language :: Python :: 3.13", + "Programming Language :: Python :: 3.14", "Programming Language :: Python :: Implementation :: CPython", "Programming Language :: Python :: Implementation :: PyPy", # Application version "Development Status :: 5 - Production/Stable" ] dependencies = [ - "opentelemetry-api>=1.26.0", - "opentelemetry-sdk>=1.26.0", + "opentelemetry-api>=1.42.0", + "opentelemetry-sdk>=1.42.0", "opentelemetry-exporter-otlp-proto-http", + "opentelemetry-instrumentation-logging>=0.63b0", "requests", "typing-extensions" ] @@ -74,7 +75,7 @@ dependencies = [ ] [[tool.hatch.envs.test.matrix]] -python = ["38", "39", "310", "311", "312"] +python = ["310", "311", "312", "313", "314"] [tool.hatch.envs.lint] detached = true @@ -87,6 +88,7 @@ dependencies = [ "opentelemetry-api", "opentelemetry-sdk", "opentelemetry-exporter-otlp-proto-http", + "opentelemetry-instrumentation-logging", "hatchling", "types-deprecated", diff --git a/src/appsignal/_once.py b/src/appsignal/_once.py index faa3aec4..78350dab 100644 --- a/src/appsignal/_once.py +++ b/src/appsignal/_once.py @@ -1,6 +1,7 @@ from __future__ import annotations -from typing import Any, Callable +from collections.abc import Callable +from typing import Any from . import internal_logger as logger diff --git a/src/appsignal/check_in/cron.py b/src/appsignal/check_in/cron.py index c68f125f..2253f6eb 100644 --- a/src/appsignal/check_in/cron.py +++ b/src/appsignal/check_in/cron.py @@ -1,8 +1,9 @@ from __future__ import annotations from binascii import hexlify +from collections.abc import Callable from os import urandom -from typing import Any, Callable, Literal, TypeVar +from typing import Any, Literal, TypeVar from .event import cron as cron_event from .scheduler import scheduler diff --git a/src/appsignal/check_in/event.py b/src/appsignal/check_in/event.py index 1afebfd3..bf0efc1b 100644 --- a/src/appsignal/check_in/event.py +++ b/src/appsignal/check_in/event.py @@ -1,14 +1,14 @@ from __future__ import annotations from time import time -from typing import Literal, TypedDict, Union +from typing import Literal, TypedDict from typing_extensions import NotRequired -EventKind = Union[Literal["start"], Literal["finish"]] +EventKind = Literal["start"] | Literal["finish"] -EventCheckInType = Union[Literal["cron"], Literal["heartbeat"]] +EventCheckInType = Literal["cron"] | Literal["heartbeat"] class Event(TypedDict): diff --git a/src/appsignal/cli/base.py b/src/appsignal/cli/base.py index 6c534b81..5373077d 100644 --- a/src/appsignal/cli/base.py +++ b/src/appsignal/cli/base.py @@ -2,7 +2,8 @@ import sys from argparse import ArgumentParser -from typing import Mapping, NoReturn +from collections.abc import Mapping +from typing import NoReturn from .command import AppsignalCLICommand from .demo import DemoCommand diff --git a/src/appsignal/config.py b/src/appsignal/config.py index ef895988..6f723203 100644 --- a/src/appsignal/config.py +++ b/src/appsignal/config.py @@ -6,7 +6,7 @@ import tempfile import urllib.parse import urllib.request -from typing import Any, ClassVar, List, Literal, TypedDict, cast, get_args +from typing import Any, ClassVar, Literal, TypedDict, cast, get_args from . import internal_logger as logger from .__about__ import __version__ @@ -161,7 +161,7 @@ class Config: "logging", ] DEFAULT_INSTRUMENTATIONS = cast( - List[DefaultInstrumentation], list(get_args(DefaultInstrumentation)) + list[DefaultInstrumentation], list(get_args(DefaultInstrumentation)) ) DEPRECATED_COLLECTOR_OPTIONS: ClassVar[dict[str, list[str]]] = { @@ -704,7 +704,7 @@ def parse_disable_default_instrumentations( return False return cast( - List[Config.DefaultInstrumentation], + list[Config.DefaultInstrumentation], [x for x in value.split(",") if x in Config.DEFAULT_INSTRUMENTATIONS], ) diff --git a/src/appsignal/heartbeat.py b/src/appsignal/heartbeat.py index 1561a99a..5d11a86e 100644 --- a/src/appsignal/heartbeat.py +++ b/src/appsignal/heartbeat.py @@ -1,6 +1,7 @@ from __future__ import annotations -from typing import Any, Callable, TypeVar +from collections.abc import Callable +from typing import Any, TypeVar from ._once import _Once, _warn_logger_and_stdout from .check_in import Cron, cron diff --git a/src/appsignal/opentelemetry.py b/src/appsignal/opentelemetry.py index fed7a52b..b0cc8528 100644 --- a/src/appsignal/opentelemetry.py +++ b/src/appsignal/opentelemetry.py @@ -1,7 +1,8 @@ from __future__ import annotations import os -from typing import TYPE_CHECKING, Callable, List, Mapping, Union, cast +from collections.abc import Callable, Mapping +from typing import TYPE_CHECKING, Any, cast import requests from opentelemetry import _logs as logs @@ -38,6 +39,8 @@ if TYPE_CHECKING: + import logging + from opentelemetry.trace.span import Span @@ -163,22 +166,148 @@ def add_logging_instrumentation(config: Config) -> None: if not config.should_instrument_logging(): return + from opentelemetry.instrumentation.logging import LoggingInstrumentor + + instrumentor = LoggingInstrumentor() + + # The handler is attached to the root logger once per process, however + # many times AppSignal is started in it. + if instrumentor.is_instrumented_by_opentelemetry: + return + + instrumentor.instrument( + log_code_attributes=True, + enable_log_auto_instrumentation=True, + ) + + _warn_about_logging_handlers() + + +# The OpenTelemetry log handler classes an application can attach itself. The +# one in the SDK is deprecated and is removed in a future release, so it is +# only looked for when it is there. +def _logging_handler_classes() -> tuple[tuple[type, ...], type | None]: + from opentelemetry.instrumentation.logging.handler import LoggingHandler + + classes: list[type] = [LoggingHandler] + deprecated: type | None = None + + try: + from opentelemetry.sdk._logs import LoggingHandler as SDKLoggingHandler + except ImportError: + pass + else: + deprecated = SDKLoggingHandler + classes.append(SDKLoggingHandler) + + return tuple(classes), deprecated + + +# What has already been warned about, as logger name and reason, so that an +# application that configures logging repeatedly is warned once for each. +_warned_logger_names: set[tuple[str, str]] = set() + + +def _warn_once(name: str, reason: str, message: str) -> None: + if (name, reason) in _warned_logger_names: + return + + _warned_logger_names.add((name, reason)) + logger.warning(message) + + +# Warn about the log handlers an application attached itself that send to the +# logger provider started here. A handler sending anywhere else belongs to +# another pipeline and is left alone. +# +# Our documentation used to advise attaching the handler in +# `opentelemetry.sdk._logs`, which is deprecated, and attaching a handler of +# your own, which duplicates the one attached here when the records it handles +# reach the root logger. +def _warn_about_logging_handlers() -> None: import logging - from opentelemetry.sdk._logs import LoggingHandler + from opentelemetry._logs import get_logger_provider + from opentelemetry.instrumentation.logging import LoggingInstrumentor + + ours = LoggingInstrumentor()._logging_handler + provider = get_logger_provider() + classes, deprecated = _logging_handler_classes() + + root = logging.getLogger() + loggers = [root] + [ + configured + for configured in root.manager.loggerDict.values() + if isinstance(configured, logging.Logger) + ] + + for configured in loggers: + for handler in configured.handlers: + if handler is ours or not isinstance(handler, classes): + continue + if getattr(handler, "_logger_provider", None) is not provider: + continue + + name = configured.name if configured is not root else "the root logger" + + if deprecated is not None and isinstance(handler, deprecated): + _warn_once( + name, + "deprecated", + f"The OpenTelemetry log handler attached to {name} is" + " imported from 'opentelemetry.sdk._logs', which is" + " deprecated and is removed in a future release. Import it" + " from 'opentelemetry.instrumentation.logging.handler'" + " instead, and construct it as" + " 'LoggingHandler(level=logging.NOTSET," + " log_code_attributes=True)' to keep reporting the file," + " function and line each log line came from.", + ) + + if ours is not None and _propagates_to_root(configured): + _warn_once( + name, + "duplicate", + f"An OpenTelemetry log handler is attached to {name}. It" + " is redundant with the handler that AppSignal" + " automatically attaches to the root logger, and it will" + " cause every log line through it to be sent twice. Remove" + " it, or set the 'disable_default_instrumentations'" + " configuration option to ['logging'] to attach the log" + " handlers yourself.", + ) + + +# Whether the records this logger handles reach the root logger. +def _propagates_to_root(configured: logging.Logger) -> bool: + import logging + + root = logging.getLogger() + + while configured is not root: + if not configured.propagate: + return False + configured = configured.parent or root + + return True - # Attach OTel LoggingHandler to the root logger - handler = LoggingHandler(level=logging.NOTSET) - logger = logging.getLogger() - logger.addHandler(handler) - # Configure the OpenTelemetry loggers and the AppSignal internal - # logger to not propagate to the root logger. This prevents - # internal logs from being sent to AppSignal. - opentelemetry_logger = logging.getLogger("opentelemetry") - opentelemetry_logger.propagate = False - appsignal_logger = logging.getLogger("appsignal") - appsignal_logger.propagate = False +# Warn again whenever the application configures the logging module, because +# that is when it attaches its own handlers. A handler attached any other way +# after this point is not seen. +def _warn_about_logging_handlers_on_reconfiguration() -> None: + import logging.config + + def wrap(configure: Callable[..., None]) -> Callable[..., None]: + def configure_and_warn(*args: Any, **kwargs: Any) -> None: + configure(*args, **kwargs) + _warn_about_logging_handlers() + + return configure_and_warn + + logging.config.dictConfig = wrap(logging.config.dictConfig) + logging.config.fileConfig = wrap(logging.config.fileConfig) + logging.basicConfig = wrap(logging.basicConfig) DefaultInstrumentationAdder = Callable[[Config], None] @@ -206,7 +335,7 @@ def add_logging_instrumentation(config: Config) -> None: } -Provider = Union[TracerProvider, MeterProvider, LoggerProvider] +Provider = TracerProvider | MeterProvider | LoggerProvider # The providers started by this module. We keep our own references rather than # reading the global providers back when stopping: no logger provider is set @@ -355,6 +484,21 @@ def _start_logging(config: Config) -> None: logs.set_logger_provider(provider) _providers.append(provider) + _silence_internal_loggers() + _warn_about_logging_handlers() + _warn_about_logging_handlers_on_reconfiguration() + + +# Keep the log lines AppSignal and the OpenTelemetry SDK write about +# themselves out of the logs sent to AppSignal. A log handler sending to the +# logger provider started here receives everything that reaches the root +# logger, whether the handler was attached here or by the application. +def _silence_internal_loggers() -> None: + import logging + + for name in ["appsignal", "opentelemetry"]: + logging.getLogger(name).propagate = False + def _resource(config: Config) -> Resource: attributes = { @@ -413,7 +557,7 @@ def _resource(config: Config) -> Resource: if value is not None } - return Resource(attributes=cast(Mapping[str, Union[str, List[str]]], attributes)) + return Resource(attributes=cast(Mapping[str, str | list[str]], attributes)) def _opentelemetry_endpoint(config: Config) -> str: diff --git a/src/appsignal/probes.py b/src/appsignal/probes.py index 324cef58..1088caa7 100644 --- a/src/appsignal/probes.py +++ b/src/appsignal/probes.py @@ -1,16 +1,17 @@ from __future__ import annotations +from collections.abc import Callable from inspect import signature from threading import Event, Lock, Thread from time import gmtime -from typing import Any, Callable, Optional, TypeVar, Union, cast +from typing import Any, TypeVar, cast from . import internal_logger as logger T = TypeVar("T") -Probe = Union[Callable[[], None], Callable[[Optional[T]], Optional[T]]] +Probe = Callable[[], None] | Callable[[T | None], T | None] # How long to wait for the probe thread to finish when stopping. Setting the # stop event wakes the thread immediately, so it only takes this long when a diff --git a/src/appsignal/tracing.py b/src/appsignal/tracing.py index b0f1942d..a165e44e 100644 --- a/src/appsignal/tracing.py +++ b/src/appsignal/tracing.py @@ -1,8 +1,9 @@ from __future__ import annotations import json +from collections.abc import Iterator from contextlib import contextmanager -from typing import TYPE_CHECKING, Any, Iterator +from typing import TYPE_CHECKING, Any from opentelemetry import trace from opentelemetry.context import Context diff --git a/tests/test_opentelemetry.py b/tests/test_opentelemetry.py index 38bf71f6..b885c399 100644 --- a/tests/test_opentelemetry.py +++ b/tests/test_opentelemetry.py @@ -1,9 +1,14 @@ from __future__ import annotations +import logging +import logging.config import os -from typing import List, cast +from typing import cast from unittest.mock import Mock +from opentelemetry.instrumentation.logging.handler import LoggingHandler +from opentelemetry.sdk._logs import LoggerProvider +from opentelemetry.sdk._logs import LoggingHandler as SDKLoggingHandler from opentelemetry.sdk.trace import TracerProvider from opentelemetry.sdk.trace.export import SimpleSpanProcessor @@ -18,6 +23,7 @@ _start_metrics, _start_tracer, add_instrumentations, + add_logging_instrumentation, stop, ) @@ -132,7 +138,7 @@ def test_disable_default_instrumentations_backwards_compatibility_prefix(): config = Config( Options( disable_default_instrumentations=cast( - List[Config.DefaultInstrumentation], + list[Config.DefaultInstrumentation], ["opentelemetry.instrumentation.celery"], ) ) @@ -154,6 +160,197 @@ def test_add_instrumentations_disable_all_default_instrumentations(): adder.assert_not_called() +def logging_handlers(): + return [ + handler + for handler in logging.getLogger().handlers + if isinstance(handler, LoggingHandler) + ] + + +def test_add_logging_instrumentation(): + config = Config(Options(collector_endpoint="https://collector.example")) + + add_logging_instrumentation(config) + + assert len(logging_handlers()) == 1 + + +def test_start_logging_silences_the_internal_loggers(): + _start_logging(Config(COLLECTOR_OPTIONS)) + + assert not logging.getLogger("appsignal").propagate + assert not logging.getLogger("opentelemetry").propagate + + +# An application that attaches the log handler itself disables the logging +# instrumentation, and a handler it attaches to the root logger receives +# whatever reaches it, including what AppSignal logs about itself. +def test_start_logging_silences_them_without_the_instrumentation(): + config = Config( + Options( + collector_endpoint="https://collector.example", + disable_default_instrumentations=["logging"], + ) + ) + + _start_logging(config) + add_instrumentations(config) + + assert logging_handlers() == [] + assert not logging.getLogger("appsignal").propagate + assert not logging.getLogger("opentelemetry").propagate + + +def test_add_logging_instrumentation_only_attaches_one_handler(): + config = Config(Options(collector_endpoint="https://collector.example")) + + add_logging_instrumentation(config) + add_logging_instrumentation(config) + + assert len(logging_handlers()) == 1 + + +def test_add_logging_instrumentation_without_a_collector(): + config = Config() + + add_logging_instrumentation(config) + + assert logging_handlers() == [] + + +def test_add_logging_instrumentation_reports_the_code_and_exception(log_records): + config = Config(Options(collector_endpoint="https://collector.example")) + add_logging_instrumentation(config) + + logger = logging.getLogger("test_add_logging_instrumentation") + logger.setLevel(logging.ERROR) + try: + raise ValueError("An exception") + except ValueError: + logger.exception("Something went wrong") + + (log_record,) = log_records() + + assert log_record.body == "Something went wrong" + assert log_record.severity_text == "ERROR" + assert log_record.attributes["code.function.name"] == ( + "test_add_logging_instrumentation_reports_the_code_and_exception" + ) + assert log_record.attributes["code.file.path"] == __file__ + assert log_record.attributes["exception.type"] == "ValueError" + assert log_record.attributes["exception.message"] == "An exception" + + +COLLECTOR_OPTIONS = Options(collector_endpoint="https://collector.example") + + +def logging_config(logger_name, handler, propagate=True): + return { + "version": 1, + "disable_existing_loggers": False, + "handlers": {"appsignal": {"()": lambda: handler}}, + "loggers": {logger_name: {"handlers": ["appsignal"], "propagate": propagate}}, + } + + +def test_add_logging_instrumentation_warns_about_a_duplicate_handler(mocker): + warning = mocker.patch("appsignal.opentelemetry.logger.warning") + _start_logging(Config(COLLECTOR_OPTIONS)) + add_logging_instrumentation(Config(COLLECTOR_OPTIONS)) + handler = LoggingHandler(level=logging.NOTSET) + + logging.config.dictConfig(logging_config("duplicate", handler)) + + assert logging.getLogger("duplicate").handlers == [handler] + assert "duplicate" in warning.call_args.args[0] + + +def test_add_logging_instrumentation_warns_about_a_handler_attached_before_it( + mocker, +): + warning = mocker.patch("appsignal.opentelemetry.logger.warning") + logging.getLogger("duplicate").addHandler(LoggingHandler(level=logging.NOTSET)) + + add_logging_instrumentation(Config(COLLECTOR_OPTIONS)) + + assert "duplicate" in warning.call_args.args[0] + + +def test_add_logging_instrumentation_warns_once_per_logger(mocker): + warning = mocker.patch("appsignal.opentelemetry.logger.warning") + _start_logging(Config(COLLECTOR_OPTIONS)) + add_logging_instrumentation(Config(COLLECTOR_OPTIONS)) + handler = LoggingHandler(level=logging.NOTSET) + + logging.config.dictConfig(logging_config("duplicate", handler)) + logging.config.dictConfig(logging_config("duplicate", handler)) + + assert warning.call_count == 1 + + +def test_start_logging_says_the_sdk_handler_is_deprecated(mocker): + warning = mocker.patch("appsignal.opentelemetry.logger.warning") + _start_logging(Config(COLLECTOR_OPTIONS)) + handler = SDKLoggingHandler(level=logging.NOTSET) + + logging.config.dictConfig(logging_config("duplicate", handler)) + + assert "deprecated" in warning.call_args.args[0] + + +# An application that attaches the handler itself disables the logging +# instrumentation, so nothing is duplicated, but the handler it was told to +# attach is still the deprecated one. +def test_start_logging_says_so_without_the_logging_instrumentation(mocker): + warning = mocker.patch("appsignal.opentelemetry.logger.warning") + _start_logging(Config(COLLECTOR_OPTIONS)) + handler = SDKLoggingHandler(level=logging.NOTSET) + + logging.config.dictConfig(logging_config("duplicate", handler)) + + assert warning.call_count == 1 + assert "deprecated" in warning.call_args.args[0] + + +def test_start_logging_says_so_for_a_logger_that_does_not_propagate(mocker): + warning = mocker.patch("appsignal.opentelemetry.logger.warning") + _start_logging(Config(COLLECTOR_OPTIONS)) + add_logging_instrumentation(Config(COLLECTOR_OPTIONS)) + handler = SDKLoggingHandler(level=logging.NOTSET) + + logging.config.dictConfig( + logging_config("duplicate_not_propagating", handler, propagate=False) + ) + + assert warning.call_count == 1 + assert "deprecated" in warning.call_args.args[0] + + +def test_add_logging_instrumentation_ignores_a_handler_that_is_the_only_one(mocker): + warning = mocker.patch("appsignal.opentelemetry.logger.warning") + _start_logging(Config(COLLECTOR_OPTIONS)) + add_logging_instrumentation(Config(COLLECTOR_OPTIONS)) + handler = LoggingHandler(level=logging.NOTSET) + + logging.config.dictConfig( + logging_config("duplicate_not_propagating", handler, propagate=False) + ) + + warning.assert_not_called() + + +def test_add_logging_instrumentation_ignores_a_handler_sending_elsewhere(mocker): + warning = mocker.patch("appsignal.opentelemetry.logger.warning") + _start_logging(Config(COLLECTOR_OPTIONS)) + add_logging_instrumentation(Config(COLLECTOR_OPTIONS)) + handler = LoggingHandler(level=logging.NOTSET, logger_provider=LoggerProvider()) + + logging.config.dictConfig(logging_config("duplicate_elsewhere", handler)) + + warning.assert_not_called() + + def test_stop_shuts_down_the_started_providers(): tracer_provider = Mock() meter_provider = Mock() diff --git a/tests/test_probes.py b/tests/test_probes.py index 1ee85733..ade317a2 100644 --- a/tests/test_probes.py +++ b/tests/test_probes.py @@ -1,6 +1,7 @@ +from collections.abc import Callable from threading import Event from time import sleep, time -from typing import Any, Callable, cast +from typing import Any, cast from appsignal import probes from appsignal.probes import ( diff --git a/tests/utils.py b/tests/utils.py index 92f256e7..01f6fb4d 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -1,5 +1,5 @@ import time -from typing import Callable +from collections.abc import Callable def wait_until(