diff --git a/CHANGELOG.md b/CHANGELOG.md index e75506344c..6bb7aefc82 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -60,6 +60,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ([#4141](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4141)) - `opentelemetry-instrumentation-pyramid`: pass request attributes at span creation ([#4139](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4139)) +- `opentelemetry-instrumentation-logging`: Move there the SDK LoggingHandler + ([#4210](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4210)) ### Fixed diff --git a/instrumentation/opentelemetry-instrumentation-logging/benchmark-requirements.txt b/instrumentation/opentelemetry-instrumentation-logging/benchmark-requirements.txt new file mode 100644 index 0000000000..44564857ef --- /dev/null +++ b/instrumentation/opentelemetry-instrumentation-logging/benchmark-requirements.txt @@ -0,0 +1 @@ +pytest-benchmark==4.0.0 diff --git a/instrumentation/opentelemetry-instrumentation-logging/benchmarks/test_benchmark_logging_handler.py b/instrumentation/opentelemetry-instrumentation-logging/benchmarks/test_benchmark_logging_handler.py new file mode 100644 index 0000000000..2f20d31835 --- /dev/null +++ b/instrumentation/opentelemetry-instrumentation-logging/benchmarks/test_benchmark_logging_handler.py @@ -0,0 +1,53 @@ +# Copyright The OpenTelemetry Authors +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import logging + +import pytest + +from opentelemetry.instrumentation.logging.handler import LoggingHandler +from opentelemetry.sdk._logs import LoggerProvider +from opentelemetry.sdk._logs.export import ( + InMemoryLogRecordExporter, + SimpleLogRecordProcessor, +) + + +def _set_up_logging_handler(level): + logger_provider = LoggerProvider() + exporter = InMemoryLogRecordExporter() + processor = SimpleLogRecordProcessor(exporter=exporter) + logger_provider.add_log_record_processor(processor) + handler = LoggingHandler(level=level, logger_provider=logger_provider) + return handler + + +def _create_logger(handler, name): + logger = logging.getLogger(name) + logger.addHandler(handler) + return logger + + +@pytest.mark.parametrize("num_loggers", [1, 10, 100, 1000]) +def test_simple_get_logger_different_names(benchmark, num_loggers): + handler = _set_up_logging_handler(level=logging.DEBUG) + loggers = [ + _create_logger(handler, str(f"logger_{i}")) for i in range(num_loggers) + ] + + def benchmark_get_logger(): + for index in range(1000): + loggers[index % num_loggers].warning("test message") + + benchmark(benchmark_get_logger) diff --git a/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py b/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py index 53197957cb..ef01884de1 100644 --- a/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py +++ b/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py @@ -15,7 +15,11 @@ # pylint: disable=empty-docstring,no-value-for-parameter,no-member,no-name-in-module """ -The OpenTelemetry `logging` integration automatically injects tracing context into +The OpenTelemetry `logging` instrumentation automatically instruments Python logging +system with an handler to convert log messages into OpenTelemetry logs. +You can disable this setting `OTEL_PYTHON_LOG_AUTO_INSTRUMENTATION` to `false`. + +The OpenTelemetry `logging` integration can inject tracing context into log statements, though it is opt-in and must be enabled explicitly by setting the environment variable `OTEL_PYTHON_LOG_CORRELATION` to `true`. @@ -59,16 +63,22 @@ from os import environ from typing import Collection +from opentelemetry._logs import get_logger_provider from opentelemetry.instrumentation.instrumentor import BaseInstrumentor from opentelemetry.instrumentation.logging.constants import ( _MODULE_DOC, DEFAULT_LOGGING_FORMAT, ) from opentelemetry.instrumentation.logging.environment_variables import ( + OTEL_PYTHON_LOG_AUTO_INSTRUMENTATION, + OTEL_PYTHON_LOG_CODE_ATTRIBUTES, OTEL_PYTHON_LOG_CORRELATION, OTEL_PYTHON_LOG_FORMAT, OTEL_PYTHON_LOG_LEVEL, ) +from opentelemetry.instrumentation.logging.handler import ( + _setup_logging_handler, +) from opentelemetry.instrumentation.logging.package import _instruments from opentelemetry.trace import ( INVALID_SPAN, @@ -86,6 +96,8 @@ "error": logging.ERROR, } +_logger = logging.getLogger(__name__) + class LoggingInstrumentor(BaseInstrumentor): # pylint: disable=empty-docstring __doc__ = f"""An instrumentor for stdlib logging module. @@ -120,6 +132,7 @@ def log_hook(span: Span, record: LogRecord): _old_factory = None _log_hook = None + _logging_handler = None def instrumentation_dependencies(self) -> Collection[str]: return _instruments @@ -199,7 +212,53 @@ def record_factory(*args, **kwargs): logging.setLogRecordFactory(record_factory) + # Here we need to handle 3 scenarios: + # - the sdk logging handler is enabled and we should do no nothing + # - the sdk logging handler is not enabled and we should setup the handler by default + # - the sdk logging handler is not enabled and the user do not want we setup the handler + sdk_autoinstrumentation_env_var = ( + environ.get( + "OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED", "notset" + ) + .strip() + .lower() + ) + if sdk_autoinstrumentation_env_var == "true": + _logger.warning( + "Skipping installation of LoggingHandler from " + "`opentelemetry-instrumentation-logging` to avoid duplicate logs. " + "The SDK's deprecated LoggingHandler is already active " + "(OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED=true). To migrate, unset " + "this environment variable. The SDK's handler will be removed in a future release." + ) + elif kwargs.get( + "enable_log_auto_instrumentation", + environ.get(OTEL_PYTHON_LOG_AUTO_INSTRUMENTATION, "true") + .strip() + .lower() + == "true", + ): + log_code_attributes = kwargs.get( + "log_code_attributes", + environ.get(OTEL_PYTHON_LOG_CODE_ATTRIBUTES, "false") + .strip() + .lower() + == "true", + ) + logger_provider = get_logger_provider() + handler = _setup_logging_handler( + logger_provider=logger_provider, + log_code_attributes=log_code_attributes, + ) + LoggingInstrumentor._logging_handler = handler + def _uninstrument(self, **kwargs): if LoggingInstrumentor._old_factory: logging.setLogRecordFactory(LoggingInstrumentor._old_factory) LoggingInstrumentor._old_factory = None + + if LoggingInstrumentor._logging_handler: + logging.getLogger().removeHandler( + LoggingInstrumentor._logging_handler + ) + LoggingInstrumentor._logging_handler = None diff --git a/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/constants.py b/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/constants.py index 5eb6798231..7d9b33ba09 100644 --- a/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/constants.py +++ b/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/constants.py @@ -16,7 +16,22 @@ _MODULE_DOC = """ -The OpenTelemetry ``logging`` integration automatically injects tracing context into log statements. +The OpenTelemetry ``logging`` instrumentation automatically instruments Python logging +with a handler to convert Python log messages into OpenTelemetry logs and export them. +You can disable this by setting ``OTEL_PYTHON_LOG_AUTO_INSTRUMENTATION`` to ``false``. + +.. warning:: + + This package provides a logging handler to replace the deprecated one in ``opentelemetry-sdk``. + Therefore if you have ``opentelemetry-instrumentation-logging`` installed, you don't need to set the + ``OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED`` environment variable to ``true``. + By default, this instrumentation does not add ``code`` namespace attributes as the SDK's logger does, but adding them can be enabled by using the + ``OTEL_PYTHON_LOG_CODE_ATTRIBUTES`` environment variable. + +Enable trace context injection +------------------------------ + +The OpenTelemetry ``logging`` integration can also be configured to inject tracing context into log statements. The integration registers a custom log record factory with the the standard library logging module that automatically inject tracing context into log record objects. Optionally, the integration can also call ``logging.basicConfig()`` to set a logging @@ -35,19 +50,25 @@ {default_logging_format} -Enable trace context injection ------------------------------- - The integration is opt-in and must be enabled explicitly by setting the environment variable ``OTEL_PYTHON_LOG_CORRELATION`` to ``true``. - -The integration always registers the custom factory that injects the tracing context into the log record objects. Setting -``OTEL_PYTHON_LOG_CORRELATION`` to ``true`` calls ``logging.basicConfig()`` to set a logging format that actually makes +Setting ``OTEL_PYTHON_LOG_CORRELATION`` to ``true`` calls ``logging.basicConfig()`` to set a logging format that actually makes use of the injected variables. - Environment variables --------------------- +.. envvar:: OTEL_PYTHON_LOG_AUTO_INSTRUMENTATION + +Set this env var to ``false`` to skip installing the logging handler provided by this package. + +The default value is ``true``. + +.. envvar:: OTEL_PYTHON_CODE_ATTRIBUTES + +Set this env var to ``true`` to add ``code`` attributes (``code.file.path``, ``code.function.name``, ``code.line.number``) to OpenTelemetry logs, referencing the Python source location that emitted each log message. + +The default value is ``false``. + .. envvar:: OTEL_PYTHON_LOG_CORRELATION This env var must be set to ``true`` in order to enable trace context injection into logs by calling ``logging.basicConfig()`` and diff --git a/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/environment_variables.py b/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/environment_variables.py index 394689265f..bad44c1994 100644 --- a/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/environment_variables.py +++ b/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/environment_variables.py @@ -12,6 +12,8 @@ # See the License for the specific language governing permissions and # limitations under the License. +OTEL_PYTHON_LOG_AUTO_INSTRUMENTATION = "OTEL_PYTHON_LOG_AUTO_INSTRUMENTATION" +OTEL_PYTHON_LOG_CODE_ATTRIBUTES = "OTEL_PYTHON_LOG_CODE_ATTRIBUTES" OTEL_PYTHON_LOG_CORRELATION = "OTEL_PYTHON_LOG_CORRELATION" OTEL_PYTHON_LOG_FORMAT = "OTEL_PYTHON_LOG_FORMAT" OTEL_PYTHON_LOG_LEVEL = "OTEL_PYTHON_LOG_LEVEL" diff --git a/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/handler.py b/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/handler.py new file mode 100644 index 0000000000..c9a890db8b --- /dev/null +++ b/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/handler.py @@ -0,0 +1,280 @@ +# Copyright The OpenTelemetry Authors +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +from __future__ import annotations + +import logging +import logging.config +import threading +import traceback +from time import time_ns +from typing import Callable + +from opentelemetry._logs import ( + LoggerProvider, + LogRecord, + NoOpLogger, + SeverityNumber, + get_logger, + get_logger_provider, +) +from opentelemetry.attributes import _VALID_ANY_VALUE_TYPES +from opentelemetry.context import get_current +from opentelemetry.semconv._incubating.attributes import code_attributes +from opentelemetry.semconv.attributes import exception_attributes +from opentelemetry.util.types import _ExtendedAttributes + + +def _setup_logging_handler( + logger_provider: LoggerProvider, log_code_attributes: bool = False +) -> LoggingHandler: + handler = LoggingHandler( + level=logging.NOTSET, + logger_provider=logger_provider, + log_code_attributes=log_code_attributes, + ) + logging.getLogger().addHandler(handler) + _overwrite_logging_config_fns(handler) + return handler + + +def _overwrite_logging_config_fns(handler: "LoggingHandler") -> None: + root = logging.getLogger() + + def wrapper(config_fn: Callable) -> Callable: + def overwritten_config_fn(*args, **kwargs): + removed_handler = False + # We don't want the OTLP handler to be modified or deleted by the logging config functions. + # So we remove it and then add it back after the function call. + if handler in root.handlers: + removed_handler = True + root.handlers.remove(handler) + try: + config_fn(*args, **kwargs) + finally: + # Ensure handler is added back if logging function throws exception. + if removed_handler: + root.addHandler(handler) + + return overwritten_config_fn + + logging.config.fileConfig = wrapper(logging.config.fileConfig) + logging.config.dictConfig = wrapper(logging.config.dictConfig) + logging.basicConfig = wrapper(logging.basicConfig) + + +# skip natural LogRecord attributes +# http://docs.python.org/library/logging.html#logrecord-attributes +_RESERVED_ATTRS = frozenset( + ( + "asctime", + "args", + "created", + "exc_info", + "exc_text", + "filename", + "funcName", + "getMessage", + "message", + "levelname", + "levelno", + "lineno", + "module", + "msecs", + "msg", + "name", + "pathname", + "process", + "processName", + "relativeCreated", + "stack_info", + "thread", + "threadName", + "taskName", + ) +) + + +class LoggingHandler(logging.Handler): + """A handler class which writes logging records, in OTLP format, to + a network destination or file. Supports signals from the `logging` module. + https://docs.python.org/3/library/logging.html + """ + + def __init__( + self, + level: int = logging.NOTSET, + logger_provider: LoggerProvider | None = None, + log_code_attributes: bool = False, + ) -> None: + super().__init__(level=level) + self._logger_provider = logger_provider or get_logger_provider() + + self._log_code_attributes = log_code_attributes + + def _get_attributes( + self, record: logging.LogRecord + ) -> _ExtendedAttributes: + attributes = { + k: v for k, v in vars(record).items() if k not in _RESERVED_ATTRS + } + + if self._log_code_attributes: + # Add standard code attributes for logs. + attributes[code_attributes.CODE_FILE_PATH] = record.pathname + attributes[code_attributes.CODE_FUNCTION_NAME] = record.funcName + attributes[code_attributes.CODE_LINE_NUMBER] = record.lineno + + if record.exc_info: + exctype, value, tb = record.exc_info + if exctype is not None: + attributes[exception_attributes.EXCEPTION_TYPE] = ( + exctype.__name__ + ) + if value is not None and value.args: + attributes[exception_attributes.EXCEPTION_MESSAGE] = str( + value.args[0] + ) + if tb is not None: + # https://opentelemetry.io/docs/specs/semconv/exceptions/exceptions-spans/#stacktrace-representation + attributes[exception_attributes.EXCEPTION_STACKTRACE] = ( + "".join(traceback.format_exception(*record.exc_info)) + ) + return attributes + + def _translate(self, record: logging.LogRecord) -> LogRecord: + timestamp = int(record.created * 1e9) + observered_timestamp = time_ns() + attributes = self._get_attributes(record) + severity_number = std_to_otel(record.levelno) + if self.formatter: + body = self.format(record) + else: + # `record.getMessage()` uses `record.msg` as a template to format + # `record.args` into. There is a special case in `record.getMessage()` + # where it will only attempt formatting if args are provided, + # otherwise, it just stringifies `record.msg`. + # + # Since the OTLP body field has a type of 'any' and the logging module + # is sometimes used in such a way that objects incorrectly end up + # set as record.msg, in those cases we would like to bypass + # `record.getMessage()` completely and set the body to the object + # itself instead of its string representation. + # For more background, see: https://github.com/open-telemetry/opentelemetry-python/pull/4216 + if not record.args and not isinstance(record.msg, str): + # if record.msg is not a value we can export, cast it to string + if not isinstance(record.msg, _VALID_ANY_VALUE_TYPES): + body = str(record.msg) + else: + body = record.msg + else: + body = record.getMessage() + + # related to https://github.com/open-telemetry/opentelemetry-python/issues/3548 + # Severity Text = WARN as defined in https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/logs/data-model.md#displaying-severity. + level_name = ( + "WARN" if record.levelname == "WARNING" else record.levelname + ) + + return LogRecord( + timestamp=timestamp, + observed_timestamp=observered_timestamp, + context=get_current() or None, + severity_text=level_name, + severity_number=severity_number, + body=body, + attributes=attributes, + ) + + def emit(self, record: logging.LogRecord) -> None: + """ + Emit a record. Skip emitting if logger is NoOp. + + The record is translated to OTel format, and then sent across the pipeline. + """ + logger = get_logger(record.name, logger_provider=self._logger_provider) + if not isinstance(logger, NoOpLogger): + logger.emit(self._translate(record)) + + def flush(self) -> None: + """ + Flushes the logging output. Skip flushing if logging_provider has no force_flush method. + """ + if hasattr(self._logger_provider, "force_flush") and callable( + self._logger_provider.force_flush # type: ignore[reportAttributeAccessIssue] + ): + # This is done in a separate thread to avoid a potential deadlock, for + # details see https://github.com/open-telemetry/opentelemetry-python/pull/4636. + thread = threading.Thread(target=self._logger_provider.force_flush) # type: ignore[reportAttributeAccessIssue] + thread.start() + + +_STD_TO_OTEL = { + 10: SeverityNumber.DEBUG, + 11: SeverityNumber.DEBUG2, + 12: SeverityNumber.DEBUG3, + 13: SeverityNumber.DEBUG4, + 14: SeverityNumber.DEBUG4, + 15: SeverityNumber.DEBUG4, + 16: SeverityNumber.DEBUG4, + 17: SeverityNumber.DEBUG4, + 18: SeverityNumber.DEBUG4, + 19: SeverityNumber.DEBUG4, + 20: SeverityNumber.INFO, + 21: SeverityNumber.INFO2, + 22: SeverityNumber.INFO3, + 23: SeverityNumber.INFO4, + 24: SeverityNumber.INFO4, + 25: SeverityNumber.INFO4, + 26: SeverityNumber.INFO4, + 27: SeverityNumber.INFO4, + 28: SeverityNumber.INFO4, + 29: SeverityNumber.INFO4, + 30: SeverityNumber.WARN, + 31: SeverityNumber.WARN2, + 32: SeverityNumber.WARN3, + 33: SeverityNumber.WARN4, + 34: SeverityNumber.WARN4, + 35: SeverityNumber.WARN4, + 36: SeverityNumber.WARN4, + 37: SeverityNumber.WARN4, + 38: SeverityNumber.WARN4, + 39: SeverityNumber.WARN4, + 40: SeverityNumber.ERROR, + 41: SeverityNumber.ERROR2, + 42: SeverityNumber.ERROR3, + 43: SeverityNumber.ERROR4, + 44: SeverityNumber.ERROR4, + 45: SeverityNumber.ERROR4, + 46: SeverityNumber.ERROR4, + 47: SeverityNumber.ERROR4, + 48: SeverityNumber.ERROR4, + 49: SeverityNumber.ERROR4, + 50: SeverityNumber.FATAL, + 51: SeverityNumber.FATAL2, + 52: SeverityNumber.FATAL3, + 53: SeverityNumber.FATAL4, +} + + +def std_to_otel(levelno: int) -> SeverityNumber: + """ + Map python log levelno as defined in https://docs.python.org/3/library/logging.html#logging-levels + to OTel log severity number as defined here: https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/logs/data-model.md#field-severitynumber + """ + if levelno < 10: + return SeverityNumber.UNSPECIFIED + if levelno > 53: + return SeverityNumber.FATAL4 + return _STD_TO_OTEL[levelno] diff --git a/instrumentation/opentelemetry-instrumentation-logging/tests/test_handler.py b/instrumentation/opentelemetry-instrumentation-logging/tests/test_handler.py new file mode 100644 index 0000000000..68c8daaa24 --- /dev/null +++ b/instrumentation/opentelemetry-instrumentation-logging/tests/test_handler.py @@ -0,0 +1,732 @@ +# Copyright The OpenTelemetry Authors +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import logging +import os +import unittest +from unittest.mock import Mock, patch + +from opentelemetry._logs import NoOpLoggerProvider, SeverityNumber +from opentelemetry._logs import get_logger as APIGetLogger +from opentelemetry.attributes import BoundedAttributes +from opentelemetry.instrumentation.logging.handler import ( + LoggingHandler, + _setup_logging_handler, +) +from opentelemetry.sdk import trace +from opentelemetry.sdk._logs import ( + LoggerProvider, + LogRecordProcessor, + ReadableLogRecord, +) +from opentelemetry.sdk.environment_variables import OTEL_ATTRIBUTE_COUNT_LIMIT +from opentelemetry.semconv._incubating.attributes import code_attributes +from opentelemetry.semconv.attributes import exception_attributes +from opentelemetry.trace import ( + INVALID_SPAN_CONTEXT, + set_span_in_context, +) + + +# pylint: disable=too-many-public-methods +class TestLoggingHandler(unittest.TestCase): + def test_handler_default_log_level(self): + processor, logger, handler = set_up_test_logging(logging.NOTSET) + + # Make sure debug messages are ignored by default + logger.debug("Debug message") + assert processor.emit_count() == 0 + + # Assert emit gets called for warning message + with self.assertLogs(level=logging.WARNING): + logger.warning("Warning message") + self.assertEqual(processor.emit_count(), 1) + + logger.removeHandler(handler) + + def test_handler_custom_log_level(self): + processor, logger, handler = set_up_test_logging(logging.ERROR) + + with self.assertLogs(level=logging.WARNING): + logger.warning("Warning message test custom log level") + # Make sure any log with level < ERROR is ignored + assert processor.emit_count() == 0 + + with self.assertLogs(level=logging.ERROR): + logger.error("Mumbai, we have a major problem") + with self.assertLogs(level=logging.CRITICAL): + logger.critical("No Time For Caution") + self.assertEqual(processor.emit_count(), 2) + + logger.removeHandler(handler) + + # pylint: disable=protected-access + def test_log_record_emit_noop(self): + noop_logger_provider = NoOpLoggerProvider() + logger_mock = APIGetLogger( + __name__, logger_provider=noop_logger_provider + ) + logger = logging.getLogger(__name__) + handler_mock = Mock(spec=LoggingHandler) + handler_mock._logger = logger_mock + handler_mock.level = logging.WARNING + logger.addHandler(handler_mock) + with self.assertLogs(level=logging.WARNING): + logger.warning("Warning message") + + logger.removeHandler(handler_mock) + + def test_log_flush_noop(self): + no_op_logger_provider = NoOpLoggerProvider() + + logger = logging.getLogger("foo") + handler = LoggingHandler( + level=logging.NOTSET, logger_provider=no_op_logger_provider + ) + logger.addHandler(handler) + + with self.assertLogs(level=logging.WARNING): + logger.warning("Warning message") + + # the LoggingHandler flush method will call the force_flush method of LoggerProvider in + # a separate thread if present. NoOpLoggerProvider is not supposed to have that + with patch( + "opentelemetry.instrumentation.logging.handler.threading" + ) as threading_mock: + logger.handlers[0].flush() + + threading_mock.Thread.assert_not_called() + + logger.removeHandler(handler) + + def test_log_record_no_span_context(self): + processor, logger, handler = set_up_test_logging(logging.WARNING) + + # Assert emit gets called for warning message + with self.assertLogs(level=logging.WARNING): + logger.warning("Warning message") + + record = processor.get_log_record(0) + + self.assertIsNotNone(record) + self.assertEqual( + record.log_record.trace_id, INVALID_SPAN_CONTEXT.trace_id + ) + self.assertEqual( + record.log_record.span_id, INVALID_SPAN_CONTEXT.span_id + ) + self.assertEqual( + record.log_record.trace_flags, + INVALID_SPAN_CONTEXT.trace_flags, + ) + + logger.removeHandler(handler) + + def test_log_record_observed_timestamp(self): + processor, logger, handler = set_up_test_logging(logging.WARNING) + + with self.assertLogs(level=logging.WARNING): + logger.warning("Warning message") + + record = processor.get_log_record(0) + self.assertIsNotNone(record.log_record.observed_timestamp) + + logger.removeHandler(handler) + + def test_log_record_user_attributes(self): + """Attributes can be injected into logs by adding them to the ReadWriteLogRecord""" + processor, logger, handler = set_up_test_logging(logging.WARNING) + + # Assert emit gets called for warning message + with self.assertLogs(level=logging.WARNING): + logger.warning("Warning message", extra={"http.status_code": 200}) + + record = processor.get_log_record(0) + + self.assertIsNotNone(record) + self.assertEqual(len(record.log_record.attributes), 1) + self.assertEqual(record.log_record.attributes["http.status_code"], 200) + self.assertTrue( + isinstance(record.log_record.attributes, BoundedAttributes) + ) + + logger.removeHandler(handler) + + def test_log_record_with_code_attributes(self): + processor, logger, handler = set_up_test_logging( + logging.WARNING, log_code_attributes=True + ) + + # Assert emit gets called for warning message + with self.assertLogs(level=logging.WARNING): + logger.warning("Warning message", extra={"http.status_code": 200}) + + record = processor.get_log_record(0) + + self.assertIsNotNone(record) + self.assertEqual(len(record.log_record.attributes), 4) + self.assertEqual(record.log_record.attributes["http.status_code"], 200) + self.assertTrue( + record.log_record.attributes[ + code_attributes.CODE_FILE_PATH + ].endswith("test_handler.py") + ) + self.assertEqual( + record.log_record.attributes[code_attributes.CODE_FUNCTION_NAME], + "test_log_record_with_code_attributes", + ) + # The line of the log statement is not a constant (changing tests may change that), + # so only check that the attribute is present. + self.assertTrue( + code_attributes.CODE_LINE_NUMBER in record.log_record.attributes + ) + self.assertTrue( + isinstance(record.log_record.attributes, BoundedAttributes) + ) + + logger.removeHandler(handler) + + def test_log_record_exception(self): + """Exception information will be included in attributes""" + processor, logger, handler = set_up_test_logging(logging.ERROR) + + try: + raise ZeroDivisionError("division by zero") + except ZeroDivisionError: + with self.assertLogs(level=logging.ERROR): + logger.exception("Zero Division Error") + + record = processor.get_log_record(0) + + self.assertIsNotNone(record) + self.assertTrue(isinstance(record.log_record.body, str)) + self.assertEqual(record.log_record.body, "Zero Division Error") + self.assertEqual( + record.log_record.attributes[exception_attributes.EXCEPTION_TYPE], + ZeroDivisionError.__name__, + ) + self.assertEqual( + record.log_record.attributes[ + exception_attributes.EXCEPTION_MESSAGE + ], + "division by zero", + ) + stack_trace = record.log_record.attributes[ + exception_attributes.EXCEPTION_STACKTRACE + ] + self.assertIsInstance(stack_trace, str) + self.assertTrue("Traceback" in stack_trace) + self.assertTrue("ZeroDivisionError" in stack_trace) + self.assertTrue("division by zero" in stack_trace) + self.assertTrue(__file__ in stack_trace) + + logger.removeHandler(handler) + + def test_log_record_recursive_exception(self): + """Exception information will be included in attributes even though it is recursive""" + processor, logger, handler = set_up_test_logging(logging.ERROR) + + try: + raise ZeroDivisionError( + ZeroDivisionError(ZeroDivisionError("division by zero")) + ) + except ZeroDivisionError: + with self.assertLogs(level=logging.ERROR): + logger.exception("Zero Division Error") + + record = processor.get_log_record(0) + + self.assertIsNotNone(record) + self.assertEqual(record.log_record.body, "Zero Division Error") + self.assertEqual( + record.log_record.attributes[exception_attributes.EXCEPTION_TYPE], + ZeroDivisionError.__name__, + ) + self.assertEqual( + record.log_record.attributes[ + exception_attributes.EXCEPTION_MESSAGE + ], + "division by zero", + ) + stack_trace = record.log_record.attributes[ + exception_attributes.EXCEPTION_STACKTRACE + ] + self.assertIsInstance(stack_trace, str) + self.assertTrue("Traceback" in stack_trace) + self.assertTrue("ZeroDivisionError" in stack_trace) + self.assertTrue("division by zero" in stack_trace) + self.assertTrue(__file__ in stack_trace) + + logger.removeHandler(handler) + + def test_log_exc_info_false(self): + """Exception information will not be included in attributes""" + processor, logger, handler = set_up_test_logging(logging.NOTSET) + + try: + raise ZeroDivisionError("division by zero") + except ZeroDivisionError: + with self.assertLogs(level=logging.ERROR): + logger.error("Zero Division Error", exc_info=False) + + record = processor.get_log_record(0) + + self.assertIsNotNone(record) + self.assertEqual(record.log_record.body, "Zero Division Error") + self.assertNotIn( + exception_attributes.EXCEPTION_TYPE, + record.log_record.attributes, + ) + self.assertNotIn( + exception_attributes.EXCEPTION_MESSAGE, + record.log_record.attributes, + ) + self.assertNotIn( + exception_attributes.EXCEPTION_STACKTRACE, + record.log_record.attributes, + ) + + logger.removeHandler(handler) + + def test_log_record_exception_with_object_payload(self): + processor, logger, handler = set_up_test_logging(logging.ERROR) + + class CustomException(Exception): + def __str__(self): + return "CustomException stringified" + + try: + raise CustomException("CustomException message") + except CustomException as exception: + with self.assertLogs(level=logging.ERROR): + logger.exception(exception) + + record = processor.get_log_record(0) + + self.assertIsNotNone(record) + self.assertTrue(isinstance(record.log_record.body, str)) + self.assertEqual(record.log_record.body, "CustomException stringified") + self.assertEqual( + record.log_record.attributes[exception_attributes.EXCEPTION_TYPE], + CustomException.__name__, + ) + self.assertEqual( + record.log_record.attributes[ + exception_attributes.EXCEPTION_MESSAGE + ], + "CustomException message", + ) + stack_trace = record.log_record.attributes[ + exception_attributes.EXCEPTION_STACKTRACE + ] + self.assertIsInstance(stack_trace, str) + self.assertTrue("Traceback" in stack_trace) + self.assertTrue("CustomException" in stack_trace) + self.assertTrue(__file__ in stack_trace) + + logger.removeHandler(handler) + + def test_log_record_trace_correlation(self): + processor, logger, handler = set_up_test_logging(logging.WARNING) + + tracer = trace.TracerProvider().get_tracer(__name__) + with tracer.start_as_current_span("test") as span: + mock_context = set_span_in_context(span) + + with patch( + "opentelemetry.sdk._logs._internal.get_current", + return_value=mock_context, + ): + with self.assertLogs(level=logging.CRITICAL): + logger.critical("Critical message within span") + + record = processor.get_log_record(0) + + self.assertEqual( + record.log_record.body, + "Critical message within span", + ) + self.assertEqual(record.log_record.severity_text, "CRITICAL") + self.assertEqual( + record.log_record.severity_number, + SeverityNumber.FATAL, + ) + self.assertEqual(record.log_record.context, mock_context) + span_context = span.get_span_context() + self.assertEqual( + record.log_record.trace_id, span_context.trace_id + ) + self.assertEqual( + record.log_record.span_id, span_context.span_id + ) + self.assertEqual( + record.log_record.trace_flags, + span_context.trace_flags, + ) + + logger.removeHandler(handler) + + def test_log_record_trace_correlation_deprecated(self): + processor, logger, handler = set_up_test_logging(logging.WARNING) + + tracer = trace.TracerProvider().get_tracer(__name__) + with tracer.start_as_current_span("test") as span: + with self.assertLogs(level=logging.CRITICAL): + logger.critical("Critical message within span") + + record = processor.get_log_record(0) + + self.assertEqual( + record.log_record.body, "Critical message within span" + ) + self.assertEqual(record.log_record.severity_text, "CRITICAL") + self.assertEqual( + record.log_record.severity_number, SeverityNumber.FATAL + ) + span_context = span.get_span_context() + self.assertEqual(record.log_record.trace_id, span_context.trace_id) + self.assertEqual(record.log_record.span_id, span_context.span_id) + self.assertEqual( + record.log_record.trace_flags, span_context.trace_flags + ) + + logger.removeHandler(handler) + + def test_warning_without_formatter(self): + processor, logger, handler = set_up_test_logging(logging.WARNING) + logger.warning("Test message") + + record = processor.get_log_record(0) + self.assertEqual(record.log_record.body, "Test message") + + logger.removeHandler(handler) + + def test_exception_without_formatter(self): + processor, logger, handler = set_up_test_logging(logging.WARNING) + logger.exception("Test exception") + + record = processor.get_log_record(0) + self.assertEqual(record.log_record.body, "Test exception") + + logger.removeHandler(handler) + + def test_warning_with_formatter(self): + processor, logger, handler = set_up_test_logging( + logging.WARNING, + formatter=logging.Formatter( + "%(name)s - %(levelname)s - %(message)s" + ), + ) + logger.warning("Test message") + + record = processor.get_log_record(0) + self.assertEqual( + record.log_record.body, "foo - WARNING - Test message" + ) + + logger.removeHandler(handler) + + def test_log_body_is_always_string_with_formatter(self): + processor, logger, handler = set_up_test_logging( + logging.WARNING, + formatter=logging.Formatter( + "%(name)s - %(levelname)s - %(message)s" + ), + ) + logger.warning(["something", "of", "note"]) + + record = processor.get_log_record(0) + self.assertIsInstance(record.log_record.body, str) + + logger.removeHandler(handler) + + @patch.dict(os.environ, {"OTEL_SDK_DISABLED": "true"}) + def test_handler_root_logger_with_disabled_sdk_does_not_go_into_recursion_error( + self, + ): + processor, logger, handler = set_up_test_logging( + logging.NOTSET, root_logger=True + ) + logger.warning("hello") + + self.assertEqual(processor.emit_count(), 0) + + logger.removeHandler(handler) + + @patch.dict(os.environ, {OTEL_ATTRIBUTE_COUNT_LIMIT: "3"}) + def test_otel_attribute_count_limit_respected_in_logging_handler(self): + """Test that OTEL_ATTRIBUTE_COUNT_LIMIT is properly respected by LoggingHandler.""" + # Create a new LoggerProvider within the patched environment + # This will create LogRecordLimits() that reads from the environment variable + logger_provider = LoggerProvider() + processor = FakeProcessor() + logger_provider.add_log_record_processor(processor) + logger = logging.getLogger("env_test") + handler = LoggingHandler( + level=logging.WARNING, logger_provider=logger_provider + ) + logger.addHandler(handler) + + # Create a log record with many extra attributes + extra_attrs = {f"custom_attr_{i}": f"value_{i}" for i in range(10)} + + with self.assertLogs(level=logging.WARNING): + logger.warning( + "Test message with many attributes", extra=extra_attrs + ) + + record = processor.get_log_record(0) + + # With OTEL_ATTRIBUTE_COUNT_LIMIT=3, should have exactly 3 attributes + total_attrs = len(record.log_record.attributes) + self.assertEqual( + total_attrs, + 3, + f"Should have exactly 3 attributes due to limit, got {total_attrs}", + ) + + # Should have 7 dropped attributes (10 custom - 3 kept = 7 dropped) + self.assertEqual( + record.dropped_attributes, + 7, + f"Should have 7 dropped attributes, got {record.dropped_attributes}", + ) + + logger.removeHandler(handler) + + @patch.dict(os.environ, {OTEL_ATTRIBUTE_COUNT_LIMIT: "5"}) + def test_otel_attribute_count_limit_includes_code_attributes(self): + """Test that OTEL_ATTRIBUTE_COUNT_LIMIT applies to all attributes including code attributes.""" + # Create a new LoggerProvider within the patched environment + # This will create LogRecordLimits() that reads from the environment variable + logger_provider = LoggerProvider() + processor = FakeProcessor() + logger_provider.add_log_record_processor(processor) + logger = logging.getLogger("env_test_2") + handler = LoggingHandler( + level=logging.WARNING, logger_provider=logger_provider + ) + logger.addHandler(handler) + + # Create a log record with some extra attributes + extra_attrs = {f"user_attr_{i}": f"value_{i}" for i in range(8)} + + with self.assertLogs(level=logging.WARNING): + logger.warning("Test message", extra=extra_attrs) + + record = processor.get_log_record(0) + + # With OTEL_ATTRIBUTE_COUNT_LIMIT=5, should have exactly 5 attributes + total_attrs = len(record.log_record.attributes) + self.assertEqual( + total_attrs, + 5, + f"Should have exactly 5 attributes due to limit, got {total_attrs}", + ) + + # Should have 3 dropped attributes (8 user - 5 kept = 3 dropped) + self.assertEqual( + record.dropped_attributes, + 3, + f"Should have 3 dropped attributes, got {record.dropped_attributes}", + ) + + logger.removeHandler(handler) + + def test_logging_handler_without_env_var_uses_default_limit(self): + """Test that without OTEL_ATTRIBUTE_COUNT_LIMIT, default limit (128) should apply.""" + processor, logger, _ = set_up_test_logging(logging.WARNING) + + # Create a log record with many attributes (more than default limit of 128) + extra_attrs = {f"attr_{i}": f"value_{i}" for i in range(150)} + + with self.assertLogs(level=logging.WARNING): + logger.warning( + "Test message with many attributes", extra=extra_attrs + ) + + record = processor.get_log_record(0) + + # Should be limited to default limit (128) total attributes + total_attrs = len(record.log_record.attributes) + self.assertEqual( + total_attrs, + 128, + f"Should have exactly 128 attributes (default limit), got {total_attrs}", + ) + + # Should have 22 dropped attributes (150 user - 128 kept = 22 dropped) + self.assertEqual( + record.dropped_attributes, + 22, + f"Should have 22 dropped attributes, got {record.dropped_attributes}", + ) + + +# pylint: disable=invalid-name +class SetupLoggingHandlerTestCase(unittest.TestCase): + def test_basicConfig_works_with_otel_handler(self): + logger_provider = LoggerProvider() + with ResetGlobalLoggingState(): + _setup_logging_handler(logger_provider=logger_provider) + + logging.basicConfig(level=logging.INFO) + + root_logger = logging.getLogger() + stream_handlers = [ + h + for h in root_logger.handlers + if isinstance(h, logging.StreamHandler) + ] + self.assertEqual( + len(stream_handlers), + 1, + "basicConfig should add a StreamHandler even when OTel handler exists", + ) + + def test_basicConfig_preserves_otel_handler(self): + logger_provider = LoggerProvider() + with ResetGlobalLoggingState(): + _setup_logging_handler(logger_provider=logger_provider) + + root_logger = logging.getLogger() + self.assertEqual( + len(root_logger.handlers), + 1, + "Should be exactly one OpenTelemetry LoggingHandler", + ) + handler = root_logger.handlers[0] + self.assertIsInstance(handler, LoggingHandler) + logging.basicConfig() + + self.assertGreater(len(root_logger.handlers), 1) + + logging_handlers = [ + h + for h in root_logger.handlers + if isinstance(h, LoggingHandler) + ] + self.assertEqual( + len(logging_handlers), + 1, + "Should still have exactly one OpenTelemetry LoggingHandler", + ) + root_logger.removeHandler(logging_handlers[0]) + + def test_dictConfig_preserves_otel_handler(self): + logger_provider = LoggerProvider() + with ResetGlobalLoggingState(): + _setup_logging_handler(logger_provider=logger_provider) + + root_logger = logging.getLogger() + self.assertEqual( + len(root_logger.handlers), + 1, + "Should be exactly one OpenTelemetry LoggingHandler", + ) + logging.config.dictConfig( + { + "version": 1, + "disable_existing_loggers": False, # If this is True all loggers are disabled. Many unit tests assert loggers emit logs. + "handlers": { + "console": { + "class": "logging.StreamHandler", + "level": "DEBUG", + "stream": "ext://sys.stdout", + }, + }, + "loggers": { + "": { # root logger + "handlers": ["console"], + }, + }, + } + ) + self.assertEqual(len(root_logger.handlers), 2) + + logging_handlers = [ + h + for h in root_logger.handlers + if isinstance(h, LoggingHandler) + ] + self.assertEqual( + len(logging_handlers), + 1, + "Should still have exactly one OpenTelemetry LoggingHandler", + ) + + root_logger.removeHandler(logging_handlers[0]) + + +def set_up_test_logging( + level, formatter=None, root_logger=False, log_code_attributes=False +): + logger_provider = LoggerProvider() + processor = FakeProcessor() + logger_provider.add_log_record_processor(processor) + logger = logging.getLogger(None if root_logger else "foo") + handler = LoggingHandler( + level=level, + logger_provider=logger_provider, + log_code_attributes=log_code_attributes, + ) + if formatter: + handler.setFormatter(formatter) + logger.addHandler(handler) + return processor, logger, handler + + +class FakeProcessor(LogRecordProcessor): + def __init__(self): + self.log_data_emitted = [] + + def on_emit(self, log_record: ReadableLogRecord): + self.log_data_emitted.append(log_record) + + def shutdown(self): + pass + + def force_flush(self, timeout_millis: int = 30000): + pass + + def emit_count(self): + return len(self.log_data_emitted) + + def get_log_record(self, i): + return self.log_data_emitted[i] + + +# Any test that calls _init_logging with setup_logging_handler=True +# should call _init_logging within this context manager, to +# ensure the global logging state is reset after the test. +class ResetGlobalLoggingState: + def __init__(self): + self.original_basic_config = logging.basicConfig + self.original_dict_config = logging.config.dictConfig + self.original_file_config = logging.config.fileConfig + self.root_logger = logging.getLogger() + self.original_handlers = None + + def __enter__(self): + self.original_handlers = self.root_logger.handlers[:] + self.root_logger.handlers = [] + return self + + def __exit__(self, exc_type, exc_val, exc_tb): + self.root_logger.handlers = [] + for handler in self.original_handlers: + self.root_logger.addHandler(handler) + logging.basicConfig = self.original_basic_config + logging.config.dictConfig = self.original_dict_config + logging.config.fileConfig = self.original_file_config diff --git a/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py b/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py index 37e635f2a4..bd1d0ddba3 100644 --- a/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py +++ b/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py @@ -18,10 +18,12 @@ import pytest -from opentelemetry.instrumentation.logging import ( # pylint: disable=no-name-in-module +from opentelemetry._logs import get_logger_provider +from opentelemetry.instrumentation.logging import ( DEFAULT_LOGGING_FORMAT, LoggingInstrumentor, ) +from opentelemetry.instrumentation.logging.handler import LoggingHandler from opentelemetry.test.test_base import TestBase from opentelemetry.trace import NoOpTracerProvider, ProxyTracer, get_tracer @@ -40,6 +42,7 @@ def get_tracer( # pylint: disable=no-self-use ) +# pylint: disable=no-self-use,too-many-public-methods class TestLoggingInstrumentorProxyTracerProvider(TestBase): @pytest.fixture(autouse=True) def inject_fixtures(self, caplog): @@ -241,6 +244,14 @@ def test_uninstrumented(self): self.assertFalse(hasattr(record, "otelTraceID")) self.assertFalse(hasattr(record, "otelTraceSampled")) + root_logger = logging.getLogger() + logging_handler_instances = [ + handler + for handler in root_logger.handlers + if isinstance(handler, LoggingHandler) + ] + self.assertEqual(logging_handler_instances, []) + def test_no_op_tracer_provider(self): LoggingInstrumentor().uninstrument() LoggingInstrumentor().instrument( @@ -257,3 +268,145 @@ def test_no_op_tracer_provider(self): self.assertEqual(record.otelTraceID, "0") self.assertEqual(record.otelServiceName, "") self.assertEqual(record.otelTraceSampled, False) + + @mock.patch.dict( + "os.environ", + {"OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED": "true"}, + ) + def test_handler_setup_is_disabled_if_sdk_autoinstrumentation_env_var_is_set_to_true( + self, + ): + LoggingInstrumentor().uninstrument() + with self.caplog.at_level(level=logging.WARNING): + LoggingInstrumentor().instrument() + + self.assertEqual(len(self.caplog.records), 1) + record = self.caplog.records[0] + self.assertEqual( + record.message, + "Skipping installation of LoggingHandler from `opentelemetry-instrumentation-logging` " + "to avoid duplicate logs. The SDK's deprecated LoggingHandler is already " + "active (OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED=true). To migrate, unset " + "this environment variable. The SDK's handler will be removed in a future release.", + ) + + root_logger = logging.getLogger() + logging_handler_instances = [ + handler + for handler in root_logger.handlers + if isinstance(handler, LoggingHandler) + ] + self.assertEqual(logging_handler_instances, []) + + @mock.patch.dict( + "os.environ", + {"OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED": "false"}, + ) + def test_handler_setup_is_enabled_if_sdk_autoinstrumentation_env_var_is_set_to_false( + self, + ): + LoggingInstrumentor().uninstrument() + with self.caplog.at_level(level=logging.WARNING): + LoggingInstrumentor().instrument() + + self.assertEqual(len(self.caplog.records), 0) + root_logger = logging.getLogger() + logging_handler_instances = [ + handler + for handler in root_logger.handlers + if isinstance(handler, LoggingHandler) + ] + self.assertEqual(len(logging_handler_instances), 1) + + @mock.patch.dict( + "os.environ", + {"OTEL_PYTHON_LOG_AUTO_INSTRUMENTATION": "false"}, + ) + def test_handler_setup_is_enabled_if_autoinstrumentation_env_var_is_set_to_false( + self, + ): + LoggingInstrumentor().uninstrument() + with self.caplog.at_level(level=logging.WARNING): + LoggingInstrumentor().instrument() + + self.assertEqual(len(self.caplog.records), 0) + root_logger = logging.getLogger() + logging_handler_instances = [ + handler + for handler in root_logger.handlers + if isinstance(handler, LoggingHandler) + ] + self.assertEqual(logging_handler_instances, []) + + def test_handler_setup_is_called_if_autoinstrumentation_env_vars_are_not_set( + self, + ): + LoggingInstrumentor().uninstrument() + with self.caplog.at_level(level=logging.WARNING): + LoggingInstrumentor().instrument() + + self.assertEqual(len(self.caplog.records), 0) + root_logger = logging.getLogger() + logging_handler_instances = [ + handler + for handler in root_logger.handlers + if isinstance(handler, LoggingHandler) + ] + self.assertEqual(len(logging_handler_instances), 1) + + def test_handler_setup_is_called_without_code_attributes_by_default(self): + LoggingInstrumentor().uninstrument() + with mock.patch( + "opentelemetry.instrumentation.logging._setup_logging_handler" + ) as setup_mock: + LoggingInstrumentor().instrument() + + logger_provider = get_logger_provider() + setup_mock.assert_called_once_with( + logger_provider=logger_provider, log_code_attributes=False + ) + + @mock.patch.dict("os.environ", {"OTEL_PYTHON_LOG_CODE_ATTRIBUTES": "true"}) + def test_handler_setup_is_called_with_code_attributes_from_env_var(self): + LoggingInstrumentor().uninstrument() + with mock.patch( + "opentelemetry.instrumentation.logging._setup_logging_handler" + ) as setup_mock: + LoggingInstrumentor().instrument() + + logger_provider = get_logger_provider() + setup_mock.assert_called_once_with( + logger_provider=logger_provider, log_code_attributes=True + ) + + def test_handler_setup_is_controlled_by_instrumentor_parameter( + self, + ): + LoggingInstrumentor().uninstrument() + with self.caplog.at_level(level=logging.WARNING): + LoggingInstrumentor().instrument( + enable_log_auto_instrumentation=False + ) + + self.assertEqual(len(self.caplog.records), 0) + root_logger = logging.getLogger() + logging_handler_instances = [ + handler + for handler in root_logger.handlers + if isinstance(handler, LoggingHandler) + ] + self.assertEqual(logging_handler_instances, []) + + def test_handler_code_attributes_is_controlled_by_instrumentor_parameter( + self, + ): + LoggingInstrumentor().uninstrument() + with mock.patch( + "opentelemetry.instrumentation.logging._setup_logging_handler" + ) as setup_mock: + LoggingInstrumentor().instrument(log_code_attributes=True) + + logger_provider = get_logger_provider() + setup_mock.assert_called_once_with( + logger_provider=logger_provider, log_code_attributes=True + ) diff --git a/tox.ini b/tox.ini index d1989a834b..350584e85a 100644 --- a/tox.ini +++ b/tox.ini @@ -211,6 +211,7 @@ envlist = py3{9,10,11,12,13,14}-test-instrumentation-logging pypy3-test-instrumentation-logging lint-instrumentation-logging + benchmark-instrumentation-logging ; opentelemetry-exporter-richconsole py3{9,10,11,12,13,14}-test-exporter-richconsole @@ -685,6 +686,7 @@ deps = logging: {[testenv]test_deps} logging: -r {toxinidir}/instrumentation/opentelemetry-instrumentation-logging/test-requirements.txt + benchmark-instrumentation-logging: -r {toxinidir}/instrumentation/opentelemetry-instrumentation-logging/benchmark-requirements.txt aiohttp-client: {[testenv]test_deps} aiohttp-client: -r {toxinidir}/instrumentation/opentelemetry-instrumentation-aiohttp-client/test-requirements.txt @@ -876,6 +878,7 @@ commands = test-instrumentation-logging: pytest {toxinidir}/instrumentation/opentelemetry-instrumentation-logging/tests {posargs} lint-instrumentation-logging: sh -c "cd instrumentation && pylint --rcfile ../.pylintrc opentelemetry-instrumentation-logging" + benchmark-instrumentation-logging: pytest {toxinidir}/instrumentation/opentelemetry-instrumentation-logging/benchmarks {posargs} --benchmark-json=instrumentation-logging-benchmark.json test-instrumentation-mysql: pytest {toxinidir}/instrumentation/opentelemetry-instrumentation-mysql/tests {posargs} lint-instrumentation-mysql: sh -c "cd instrumentation && pylint --rcfile ../.pylintrc opentelemetry-instrumentation-mysql"