From c5949135025dc85e573e3b036166faa029bc0fa7 Mon Sep 17 00:00:00 2001 From: Noemi Lapresta Date: Wed, 30 Sep 2026 15:33:39 +0200 Subject: [PATCH 1/4] Require Python 3.10 The `opentelemetry-instrumentation-logging` package requires Python 3.9, and its last release supporting 3.9 pins the OpenTelemetry stack to versions that no longer move. Requiring 3.10 puts every supported Python version on the same OpenTelemetry release. Python 3.13 and 3.14 join the test matrix and the classifiers. Ruff reads `requires-python` to decide which rewrites apply, so raising the floor turns on the pyupgrade rules that account for the rest of this change. --- .changesets/require-python-3-10.md | 6 ++++++ .github/workflows/ci.yml | 2 +- .python-version | 4 ++-- conftest.py | 3 ++- pyproject.toml | 8 ++++---- src/appsignal/_once.py | 3 ++- src/appsignal/check_in/cron.py | 3 ++- src/appsignal/check_in/event.py | 6 +++--- src/appsignal/cli/base.py | 3 ++- src/appsignal/config.py | 6 +++--- src/appsignal/heartbeat.py | 3 ++- src/appsignal/opentelemetry.py | 7 ++++--- src/appsignal/probes.py | 5 +++-- src/appsignal/tracing.py | 3 ++- tests/test_opentelemetry.py | 4 ++-- tests/test_probes.py | 3 ++- tests/utils.py | 2 +- 17 files changed, 43 insertions(+), 28 deletions(-) create mode 100644 .changesets/require-python-3-10.md 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/.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..e9aa8fb9 100644 --- a/conftest.py +++ b/conftest.py @@ -4,8 +4,9 @@ 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.metrics import set_meter_provider diff --git a/pyproject.toml b/pyproject.toml index bb2cdc27..268ab5db 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,11 +15,11 @@ 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 @@ -74,7 +74,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 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..08651c33 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, cast import requests from opentelemetry import _logs as logs @@ -206,7 +207,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 @@ -413,7 +414,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..9478ff08 100644 --- a/tests/test_opentelemetry.py +++ b/tests/test_opentelemetry.py @@ -1,7 +1,7 @@ from __future__ import annotations import os -from typing import List, cast +from typing import cast from unittest.mock import Mock from opentelemetry.sdk.trace import TracerProvider @@ -132,7 +132,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"], ) ) 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( From 7941398a5f6885a8c84148f1e1b076c3574a2760 Mon Sep 17 00:00:00 2001 From: Noemi Lapresta Date: Wed, 30 Sep 2026 15:38:13 +0200 Subject: [PATCH 2/4] Attach the OpenTelemetry logging handler The log handler attached to the root logger comes from `opentelemetry.sdk._logs`, which is deprecated, and configuring the logging module removes it, so a Django application's `LOGGING` setting stops logs being sent. The handler in `opentelemetry-instrumentation-logging` wraps `dictConfig`, `fileConfig` and `basicConfig` so that it survives them. It records the file, function and line a log line came from only when asked, so `log_code_attributes` is passed to keep those attributes. Wrapping `basicConfig` means the level it is given now applies, because Python skips that call when the root logger already has a handler. An application that calls it with a level below `WARNING` starts sending those log lines. --- ...ply-the-log-level-set-with-basic-config.md | 6 ++ ...sending-logs-when-logging-is-configured.md | 8 +++ .../send-a-non-string-log-message-as-text.md | 12 ++++ .../send-one-log-line-per-forked-process.md | 6 ++ conftest.py | 53 ++++++++++++++++ pyproject.toml | 6 +- src/appsignal/opentelemetry.py | 25 +++++--- tests/test_opentelemetry.py | 61 +++++++++++++++++++ 8 files changed, 168 insertions(+), 9 deletions(-) create mode 100644 .changesets/apply-the-log-level-set-with-basic-config.md create mode 100644 .changesets/keep-sending-logs-when-logging-is-configured.md create mode 100644 .changesets/send-a-non-string-log-message-as-text.md create mode 100644 .changesets/send-one-log-line-per-forked-process.md 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-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/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/conftest.py b/conftest.py index e9aa8fb9..01018383 100644 --- a/conftest.py +++ b/conftest.py @@ -1,5 +1,7 @@ from __future__ import annotations +import logging +import logging.config import os import platform import tempfile @@ -9,7 +11,13 @@ 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 @@ -138,6 +146,51 @@ 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 + + +# Logging instrumentation attaches a handler to the root logger and marks +# itself as instrumented, both of which outlive the test that started it. +@pytest.fixture(scope="function", autouse=True) +def reset_logging_instrumentation() -> Any: + yield + + from opentelemetry.instrumentation.logging import LoggingInstrumentor + + instrumentor = LoggingInstrumentor() + if instrumentor.is_instrumented_by_opentelemetry: + instrumentor.uninstrument() + + for name in ["appsignal", "opentelemetry"]: + logging.getLogger(name).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 268ab5db..686c41b9 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -26,9 +26,10 @@ classifiers = [ "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" ] @@ -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/opentelemetry.py b/src/appsignal/opentelemetry.py index 08651c33..af8aaeab 100644 --- a/src/appsignal/opentelemetry.py +++ b/src/appsignal/opentelemetry.py @@ -39,6 +39,7 @@ if TYPE_CHECKING: + from opentelemetry.trace.span import Span @@ -166,21 +167,31 @@ def add_logging_instrumentation(config: Config) -> None: import logging - from opentelemetry.sdk._logs import LoggingHandler - - # Attach OTel LoggingHandler to the root logger - handler = LoggingHandler(level=logging.NOTSET) - logger = logging.getLogger() - logger.addHandler(handler) + from opentelemetry.instrumentation.logging import LoggingInstrumentor # 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. + # internal logs from being sent to AppSignal. This has to happen + # before the handler is attached, because attaching it emits a + # warning through the OpenTelemetry logger when it was attached + # already. opentelemetry_logger = logging.getLogger("opentelemetry") opentelemetry_logger.propagate = False appsignal_logger = logging.getLogger("appsignal") appsignal_logger.propagate = False + 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, + ) + DefaultInstrumentationAdder = Callable[[Config], None] diff --git a/tests/test_opentelemetry.py b/tests/test_opentelemetry.py index 9478ff08..b60d6fed 100644 --- a/tests/test_opentelemetry.py +++ b/tests/test_opentelemetry.py @@ -1,9 +1,11 @@ from __future__ import annotations +import logging import os from typing import cast from unittest.mock import Mock +from opentelemetry.instrumentation.logging.handler import LoggingHandler from opentelemetry.sdk.trace import TracerProvider from opentelemetry.sdk.trace.export import SimpleSpanProcessor @@ -18,6 +20,7 @@ _start_metrics, _start_tracer, add_instrumentations, + add_logging_instrumentation, stop, ) @@ -154,6 +157,64 @@ 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 + 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" + + def test_stop_shuts_down_the_started_providers(): tracer_provider = Mock() meter_provider = Mock() From d2c9c54ca849359c203b0a9083b2828689b2a203 Mon Sep 17 00:00:00 2001 From: Noemi Lapresta Date: Wed, 30 Sep 2026 15:38:37 +0200 Subject: [PATCH 3/4] Warn about log handlers the application attached An application that attached an OpenTelemetry log handler of its own now has two handlers sending to the same place, so every log line reaching both is sent twice. Our documentation told Django applications to attach one. Only a handler sending to the logger provider started here is warned about, and only when the records it handles reach the root logger, where the handler attached here receives them too. A handler from `opentelemetry.sdk._logs` is warned about separately, whether or not it duplicates anything, because it is deprecated and is removed in a future release. It raises a `DeprecationWarning` about itself, which Python hides unless it comes from `__main__`, so an application that attaches it from its settings never sees it. --- .../warn-about-the-deprecated-log-handler.md | 6 + conftest.py | 26 +++- src/appsignal/opentelemetry.py | 135 +++++++++++++++++- tests/test_opentelemetry.py | 112 +++++++++++++++ 4 files changed, 276 insertions(+), 3 deletions(-) create mode 100644 .changesets/warn-about-the-deprecated-log-handler.md 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/conftest.py b/conftest.py index 01018383..f86ce628 100644 --- a/conftest.py +++ b/conftest.py @@ -175,10 +175,17 @@ def get_and_clear_log_records() -> tuple[LogRecord, ...]: yield get_and_clear_log_records -# Logging instrumentation attaches a handler to the root logger and marks -# itself as instrumented, both of which outlive the test that started it. +# Logging instrumentation attaches a handler to the root logger, wraps the +# functions that configure the logging module, and marks itself as +# instrumented, all of which outlive the test that started it. @pytest.fixture(scope="function", autouse=True) def reset_logging_instrumentation() -> Any: + configure_functions = ( + logging.basicConfig, + logging.config.dictConfig, + logging.config.fileConfig, + ) + yield from opentelemetry.instrumentation.logging import LoggingInstrumentor @@ -187,9 +194,24 @@ def reset_logging_instrumentation() -> Any: if instrumentor.is_instrumented_by_opentelemetry: instrumentor.uninstrument() + ( + logging.basicConfig, + logging.config.dictConfig, + logging.config.fileConfig, + ) = configure_functions + for name in ["appsignal", "opentelemetry"]: logging.getLogger(name).propagate = True + 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: diff --git a/src/appsignal/opentelemetry.py b/src/appsignal/opentelemetry.py index af8aaeab..0af397c2 100644 --- a/src/appsignal/opentelemetry.py +++ b/src/appsignal/opentelemetry.py @@ -2,7 +2,7 @@ import os from collections.abc import Callable, Mapping -from typing import TYPE_CHECKING, cast +from typing import TYPE_CHECKING, Any, cast import requests from opentelemetry import _logs as logs @@ -39,6 +39,7 @@ if TYPE_CHECKING: + import logging from opentelemetry.trace.span import Span @@ -192,6 +193,135 @@ def add_logging_instrumentation(config: Config) -> None: 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._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 + + +# 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] @@ -367,6 +497,9 @@ def _start_logging(config: Config) -> None: logs.set_logger_provider(provider) _providers.append(provider) + _warn_about_logging_handlers() + _warn_about_logging_handlers_on_reconfiguration() + def _resource(config: Config) -> Resource: attributes = { diff --git a/tests/test_opentelemetry.py b/tests/test_opentelemetry.py index b60d6fed..b84352c2 100644 --- a/tests/test_opentelemetry.py +++ b/tests/test_opentelemetry.py @@ -1,11 +1,14 @@ from __future__ import annotations import logging +import logging.config import os 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 @@ -215,6 +218,115 @@ def test_add_logging_instrumentation_reports_the_code_and_exception(log_records) 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() From 3ca65d0a101da0ac00060ca5df4d54da179c3bd9 Mon Sep 17 00:00:00 2001 From: Noemi Lapresta Date: Wed, 30 Sep 2026 15:53:24 +0200 Subject: [PATCH 4/4] Keep internal logs out of an application's logs The `appsignal` and `opentelemetry` loggers are stopped from propagating to the root logger when the log handler is attached here, so an application that attaches the handler itself, through the `disable_default_instrumentations` option, sends what AppSignal and the OpenTelemetry SDK log about themselves as its own logs. Stopping the two loggers when logging starts covers a handler attached either way. --- .../keep-internal-logs-out-of-your-logs.md | 6 +++++ conftest.py | 15 +++++++---- src/appsignal/opentelemetry.py | 25 +++++++++---------- tests/test_opentelemetry.py | 24 ++++++++++++++++++ 4 files changed, 52 insertions(+), 18 deletions(-) create mode 100644 .changesets/keep-internal-logs-out-of-your-logs.md 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/conftest.py b/conftest.py index f86ce628..d1a1deb0 100644 --- a/conftest.py +++ b/conftest.py @@ -175,9 +175,10 @@ def get_and_clear_log_records() -> tuple[LogRecord, ...]: yield get_and_clear_log_records -# Logging instrumentation attaches a handler to the root logger, wraps the -# functions that configure the logging module, and marks itself as -# instrumented, all of which outlive the test that started it. +# 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 = ( @@ -185,6 +186,10 @@ def reset_logging_instrumentation() -> Any: logging.config.dictConfig, logging.config.fileConfig, ) + propagate = { + name: logging.getLogger(name).propagate + for name in ["appsignal", "opentelemetry"] + } yield @@ -200,8 +205,8 @@ def reset_logging_instrumentation() -> Any: logging.config.fileConfig, ) = configure_functions - for name in ["appsignal", "opentelemetry"]: - logging.getLogger(name).propagate = True + for name, propagates in propagate.items(): + logging.getLogger(name).propagate = propagates from appsignal.opentelemetry import _warned_logger_names diff --git a/src/appsignal/opentelemetry.py b/src/appsignal/opentelemetry.py index 0af397c2..b0cc8528 100644 --- a/src/appsignal/opentelemetry.py +++ b/src/appsignal/opentelemetry.py @@ -166,21 +166,8 @@ def add_logging_instrumentation(config: Config) -> None: if not config.should_instrument_logging(): return - import logging - from opentelemetry.instrumentation.logging import LoggingInstrumentor - # 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. This has to happen - # before the handler is attached, because attaching it emits a - # warning through the OpenTelemetry logger when it was attached - # already. - opentelemetry_logger = logging.getLogger("opentelemetry") - opentelemetry_logger.propagate = False - appsignal_logger = logging.getLogger("appsignal") - appsignal_logger.propagate = False - instrumentor = LoggingInstrumentor() # The handler is attached to the root logger once per process, however @@ -497,10 +484,22 @@ 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 = { key: value diff --git a/tests/test_opentelemetry.py b/tests/test_opentelemetry.py index b84352c2..b885c399 100644 --- a/tests/test_opentelemetry.py +++ b/tests/test_opentelemetry.py @@ -174,6 +174,30 @@ def test_add_logging_instrumentation(): 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