diff --git a/CHANGELOG.md b/CHANGELOG.md index 9130b344751..d50fb931713 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## Unreleased +- logs: add exception support to Logger emit and LogRecord attributes + ([#4907](https://github.com/open-telemetry/opentelemetry-python/issues/4907)) - `opentelemetry-sdk`: Add file configuration support with YAML/JSON loading, environment variable substitution, and schema validation against the vendored OTel config JSON schema ([#4898](https://github.com/open-telemetry/opentelemetry-python/pull/4898)) - Fix intermittent CI failures in `getting-started` and `tracecontext` jobs caused by GitHub git CDN SHA propagation lag by installing contrib packages from the already-checked-out local copy instead of a second git clone diff --git a/opentelemetry-api/src/opentelemetry/_logs/_internal/__init__.py b/opentelemetry-api/src/opentelemetry/_logs/_internal/__init__.py index bbcfcddc846..b437c1755cb 100644 --- a/opentelemetry-api/src/opentelemetry/_logs/_internal/__init__.py +++ b/opentelemetry-api/src/opentelemetry/_logs/_internal/__init__.py @@ -76,6 +76,7 @@ def __init__( body: AnyValue = None, attributes: Optional[_ExtendedAttributes] = None, event_name: Optional[str] = None, + exception: Optional[BaseException] = None, ) -> None: ... @overload @@ -110,6 +111,7 @@ def __init__( body: AnyValue = None, attributes: Optional[_ExtendedAttributes] = None, event_name: Optional[str] = None, + exception: Optional[BaseException] = None, ) -> None: if not context: context = get_current() @@ -127,6 +129,7 @@ def __init__( self.body = body self.attributes = attributes self.event_name = event_name + self.exception = exception class Logger(ABC): @@ -157,6 +160,7 @@ def emit( body: AnyValue | None = None, attributes: _ExtendedAttributes | None = None, event_name: str | None = None, + exception: BaseException | None = None, ) -> None: ... @overload @@ -178,6 +182,7 @@ def emit( body: AnyValue | None = None, attributes: _ExtendedAttributes | None = None, event_name: str | None = None, + exception: BaseException | None = None, ) -> None: """Emits a :class:`LogRecord` representing a log to the processing pipeline.""" @@ -200,6 +205,7 @@ def emit( body: AnyValue | None = None, attributes: _ExtendedAttributes | None = None, event_name: str | None = None, + exception: BaseException | None = None, ) -> None: ... @overload @@ -220,6 +226,7 @@ def emit( body: AnyValue | None = None, attributes: _ExtendedAttributes | None = None, event_name: str | None = None, + exception: BaseException | None = None, ) -> None: pass @@ -266,6 +273,7 @@ def emit( body: AnyValue | None = None, attributes: _ExtendedAttributes | None = None, event_name: str | None = None, + exception: BaseException | None = None, ) -> None: ... @overload @@ -286,9 +294,10 @@ def emit( body: AnyValue | None = None, attributes: _ExtendedAttributes | None = None, event_name: str | None = None, + exception: BaseException | None = None, ) -> None: if record: - self._logger.emit(record) + self._logger.emit(record, exception=exception) else: self._logger.emit( timestamp=timestamp, @@ -299,6 +308,7 @@ def emit( body=body, attributes=attributes, event_name=event_name, + exception=exception, ) diff --git a/opentelemetry-api/tests/logs/test_log_record.py b/opentelemetry-api/tests/logs/test_log_record.py index a06ed8dabfc..da0f41e3b6b 100644 --- a/opentelemetry-api/tests/logs/test_log_record.py +++ b/opentelemetry-api/tests/logs/test_log_record.py @@ -25,3 +25,8 @@ class TestLogRecord(unittest.TestCase): def test_log_record_observed_timestamp_default(self, time_ns_mock): # type: ignore time_ns_mock.return_value = OBSERVED_TIMESTAMP self.assertEqual(LogRecord().observed_timestamp, OBSERVED_TIMESTAMP) + + def test_log_record_exception(self): + exc = ValueError("boom") + log_record = LogRecord(exception=exc) + self.assertIs(log_record.exception, exc) diff --git a/opentelemetry-api/tests/logs/test_proxy.py b/opentelemetry-api/tests/logs/test_proxy.py index d72ccc7c6b2..f7744e5f368 100644 --- a/opentelemetry-api/tests/logs/test_proxy.py +++ b/opentelemetry-api/tests/logs/test_proxy.py @@ -15,6 +15,7 @@ # pylint: disable=W0212,W0222,W0221 import typing import unittest +from unittest.mock import Mock import opentelemetry._logs._internal as _logs_internal from opentelemetry import _logs @@ -46,6 +47,7 @@ def emit( body=None, attributes=None, event_name=None, + exception: typing.Optional[BaseException] = None, ) -> None: pass @@ -74,3 +76,16 @@ def test_proxy_logger(self): # references to the old provider still work but return real logger now real_logger = provider.get_logger("proxy-test") self.assertIsInstance(real_logger, LoggerTest) + + def test_proxy_logger_forwards_exception_with_record(self): + logger = _logs_internal.ProxyLogger("proxy-test") + logger._real_logger = Mock(spec=LoggerTest("proxy-test")) + record = _logs.LogRecord() + exception = ValueError("boom") + + self.assertIsNotNone(logger._real_logger) + logger.emit(record, exception=exception) + + logger._real_logger.emit.assert_called_once_with( + record, exception=exception + ) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py index 9029f867a7e..72625b8c349 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py @@ -516,6 +516,72 @@ def force_flush(self, timeout_millis: int = 30000) -> bool: ) +def _get_exception_attributes( + exception: BaseException, +) -> dict[str, AnyValue]: + stacktrace = "".join( + traceback.format_exception( + type(exception), value=exception, tb=exception.__traceback__ + ) + ) + module = type(exception).__module__ + qualname = type(exception).__qualname__ + exception_type = ( + f"{module}.{qualname}" if module and module != "builtins" else qualname + ) + return { + exception_attributes.EXCEPTION_TYPE: exception_type, + exception_attributes.EXCEPTION_MESSAGE: str(exception), + exception_attributes.EXCEPTION_STACKTRACE: stacktrace, + } + + +def _get_attributes_with_exception( + attributes: _ExtendedAttributes | None, + exception: BaseException | None, +) -> _ExtendedAttributes | None: + if exception is None: + return attributes + + exception_attributes_map = _get_exception_attributes(exception) + attributes = attributes or {} + if isinstance(attributes, BoundedAttributes): + merged = BoundedAttributes( + maxlen=attributes.maxlen, + attributes=attributes, + immutable=False, + max_value_len=attributes.max_value_len, + extended_attributes=attributes._extended_attributes, # pylint: disable=protected-access + ) + merged.dropped = attributes.dropped + for key, value in exception_attributes_map.items(): + if key not in merged: + merged[key] = value + return merged + + return exception_attributes_map | dict(attributes) + + +def _copy_log_record( + record: LogRecord, + attributes: _ExtendedAttributes | None, +) -> LogRecord: + return LogRecord( + timestamp=record.timestamp, + observed_timestamp=record.observed_timestamp, + context=record.context, + trace_id=record.trace_id, + span_id=record.span_id, + trace_flags=record.trace_flags, + severity_text=record.severity_text, + severity_number=record.severity_number, + body=record.body, + attributes=attributes, + event_name=record.event_name, + exception=getattr(record, "exception", None), + ) + + 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. @@ -671,13 +737,28 @@ def emit( body: AnyValue | None = None, attributes: _ExtendedAttributes | None = None, event_name: str | None = None, + exception: BaseException | None = None, ) -> None: """Emits the :class:`ReadWriteLogRecord` by setting instrumentation scope and forwarding to the processor. """ # If a record is provided, use it directly if record is not None: + record_exception = exception or getattr(record, "exception", None) + if record_exception is None and isinstance( + record, ReadWriteLogRecord + ): + record_exception = getattr( + record.log_record, "exception", None + ) if not isinstance(record, ReadWriteLogRecord): + if record_exception is not None: + record = _copy_log_record( + record, + _get_attributes_with_exception( + record.attributes, record_exception + ), + ) # pylint:disable=protected-access writable_record = ReadWriteLogRecord._from_api_log_record( record=record, @@ -685,9 +766,15 @@ def emit( instrumentation_scope=self._instrumentation_scope, ) else: + record.log_record.attributes = _get_attributes_with_exception( + record.log_record.attributes, record_exception + ) writable_record = record else: # Create a record from individual parameters + log_record_attributes = _get_attributes_with_exception( + attributes, exception + ) log_record = LogRecord( timestamp=timestamp, observed_timestamp=observed_timestamp, @@ -695,8 +782,9 @@ def emit( severity_number=severity_number, severity_text=severity_text, body=body, - attributes=attributes, + attributes=log_record_attributes, event_name=event_name, + exception=exception, ) # pylint:disable=protected-access writable_record = ReadWriteLogRecord._from_api_log_record( diff --git a/opentelemetry-sdk/tests/logs/test_logs.py b/opentelemetry-sdk/tests/logs/test_logs.py index 6a9c95685cd..cbbbdd8d5c6 100644 --- a/opentelemetry-sdk/tests/logs/test_logs.py +++ b/opentelemetry-sdk/tests/logs/test_logs.py @@ -18,12 +18,14 @@ from unittest.mock import Mock, patch from opentelemetry._logs import LogRecord, SeverityNumber +from opentelemetry.attributes import BoundedAttributes from opentelemetry.context import get_current from opentelemetry.metrics import NoOpMeterProvider from opentelemetry.sdk._logs import ( Logger, LoggerProvider, ReadableLogRecord, + ReadWriteLogRecord, ) from opentelemetry.sdk._logs._internal import ( LoggerMetrics, @@ -33,6 +35,7 @@ from opentelemetry.sdk.environment_variables import OTEL_SDK_DISABLED from opentelemetry.sdk.resources import Resource from opentelemetry.sdk.util.instrumentation import InstrumentationScope +from opentelemetry.semconv.attributes import exception_attributes class TestLoggerProvider(unittest.TestCase): @@ -217,3 +220,109 @@ def test_can_emit_with_keywords_arguments(self): self.assertEqual(result_log_record.attributes, {"some": "attributes"}) self.assertEqual(result_log_record.event_name, "event_name") self.assertEqual(log_data.resource, logger.resource) + + def test_emit_with_exception_adds_attributes(self): + logger, log_record_processor_mock = self._get_logger() + exc = ValueError("boom") + + logger.emit(body="a log line", exception=exc) + log_record_processor_mock.on_emit.assert_called_once() + log_data = log_record_processor_mock.on_emit.call_args.args[0] + attributes = dict(log_data.log_record.attributes) + self.assertEqual( + attributes[exception_attributes.EXCEPTION_TYPE], "ValueError" + ) + self.assertEqual( + attributes[exception_attributes.EXCEPTION_MESSAGE], "boom" + ) + self.assertIn( + "ValueError: boom", + attributes[exception_attributes.EXCEPTION_STACKTRACE], + ) + + def test_emit_with_raised_exception_has_stacktrace(self): + logger, log_record_processor_mock = self._get_logger() + + try: + raise ValueError("boom") + except ValueError as exc: + logger.emit(body="error", exception=exc) + + log_record_processor_mock.on_emit.assert_called_once() + log_data = log_record_processor_mock.on_emit.call_args.args[0] + stacktrace = dict(log_data.log_record.attributes)[ + exception_attributes.EXCEPTION_STACKTRACE + ] + self.assertIn("Traceback (most recent call last)", stacktrace) + self.assertIn("raise ValueError", stacktrace) + + def test_emit_logrecord_exception_preserves_user_attributes(self): + logger, log_record_processor_mock = self._get_logger() + exc = ValueError("boom") + log_record = LogRecord( + observed_timestamp=0, + body="a log line", + attributes={exception_attributes.EXCEPTION_TYPE: "custom"}, + exception=exc, + ) + + logger.emit(log_record) + log_record_processor_mock.on_emit.assert_called_once() + log_data = log_record_processor_mock.on_emit.call_args.args[0] + attributes = dict(log_data.log_record.attributes) + self.assertEqual( + attributes[exception_attributes.EXCEPTION_TYPE], "custom" + ) + self.assertEqual( + attributes[exception_attributes.EXCEPTION_MESSAGE], "boom" + ) + + def test_emit_logrecord_exception_with_immutable_attributes(self): + logger, log_record_processor_mock = self._get_logger() + exc = ValueError("boom") + original_attributes = BoundedAttributes( + attributes={"custom": "value"}, + immutable=True, + extended_attributes=True, + ) + log_record = LogRecord( + observed_timestamp=0, + body="a log line", + attributes=original_attributes, + exception=exc, + ) + + logger.emit(log_record) + + self.assertNotIn( + exception_attributes.EXCEPTION_TYPE, log_record.attributes + ) + log_record_processor_mock.on_emit.assert_called_once() + log_data = log_record_processor_mock.on_emit.call_args.args[0] + attributes = dict(log_data.log_record.attributes) + self.assertEqual(attributes["custom"], "value") + self.assertEqual( + attributes[exception_attributes.EXCEPTION_TYPE], "ValueError" + ) + + def test_emit_readwrite_logrecord_uses_exception(self): + logger, log_record_processor_mock = self._get_logger() + exc = RuntimeError("kaput") + log_record = LogRecord( + observed_timestamp=0, + body="a log line", + exception=exc, + ) + readwrite = ReadWriteLogRecord( + log_record=log_record, + resource=Resource.create({}), + instrumentation_scope=logger._instrumentation_scope, + ) + + logger.emit(readwrite) + log_record_processor_mock.on_emit.assert_called_once() + log_data = log_record_processor_mock.on_emit.call_args.args[0] + attributes = dict(log_data.log_record.attributes) + self.assertEqual( + attributes[exception_attributes.EXCEPTION_TYPE], "RuntimeError" + )