Add OTLPHandler for standard library logging module (open-telemetry#1903

)

CHANGELOG.md

@@ -93,6 +93,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 ### Added
 - Add global LogEmitterProvider and convenience function get_log_emitter
   ([#1901](https://github.com/open-telemetry/opentelemetry-python/pull/1901))
+- Add OTLPHandler for standard library logging module
+  ([#1903](https://github.com/open-telemetry/opentelemetry-python/pull/1903))
 
 ### Changed
 - Updated `opentelemetry-opencensus-exporter` to use `service_name` of spans instead of resource

opentelemetry-sdk/src/opentelemetry/sdk/logs/__init__.py

@@ -21,9 +21,10 @@
 from opentelemetry.sdk.environment_variables import (
     OTEL_PYTHON_LOG_EMITTER_PROVIDER,
 )
-from opentelemetry.sdk.logs.severity import SeverityNumber
+from opentelemetry.sdk.logs.severity import SeverityNumber, std_to_otlp
 from opentelemetry.sdk.resources import Resource
 from opentelemetry.sdk.util.instrumentation import InstrumentationInfo
+from opentelemetry.trace import get_current_span
 from opentelemetry.trace.span import TraceFlags
 from opentelemetry.util._providers import _load_provider
 from opentelemetry.util.types import Attributes
@@ -111,6 +112,48 @@ def force_flush(self, timeout_millis: int = 30000):
         """
 
 
+class OTLPHandler(logging.Handler):
+    """A handler class which writes logging records, in OTLP format, to
+    a network destination or file.
+    """
+
+    def __init__(self, level=logging.NOTSET, log_emitter=None) -> None:
+        super().__init__(level=level)
+        self._log_emitter = log_emitter or get_log_emitter(__name__)
+
+    def _translate(self, record: logging.LogRecord) -> LogRecord:
+        timestamp = int(record.created * 1e9)
+        span_context = get_current_span().get_span_context()
+        # TODO: attributes (or resource attributes?) from record metadata
+        attributes: Attributes = {}
+        severity_number = std_to_otlp(record.levelno)
+        return LogRecord(
+            timestamp=timestamp,
+            trace_id=span_context.trace_id,
+            span_id=span_context.span_id,
+            trace_flags=span_context.trace_flags,
+            severity_text=record.levelname,
+            severity_number=severity_number,
+            body=record.getMessage(),
+            resource=self._log_emitter.resource,
+            attributes=attributes,
+        )
+
+    def emit(self, record: logging.LogRecord) -> None:
+        """
+        Emit a record.
+
+        The record is translated to OTLP format, and then sent across the pipeline.
+        """
+        self._log_emitter.emit(self._translate(record))
+
+    def flush(self) -> None:
+        """
+        Flushes the logging output.
+        """
+        self._log_emitter.flush()
+
+
 class LogEmitter:
     # TODO: Add multi_log_processor
     def __init__(
@@ -121,6 +164,10 @@ def __init__(
         self._resource = resource
         self._instrumentation_info = instrumentation_info
 
+    @property
+    def resource(self):
+        return self._resource
+
     def emit(self, record: LogRecord):
         # TODO: multi_log_processor.emit
         pass
@@ -142,6 +189,10 @@ def __init__(
         if shutdown_on_exit:
             self._at_exit_handler = atexit.register(self.shutdown)
 
+    @property
+    def resource(self):
+        return self._resource
+
     def get_log_emitter(
         self,
         instrumenting_module_name: str,

opentelemetry-sdk/src/opentelemetry/sdk/logs/severity.py

@@ -54,3 +54,63 @@ class SeverityNumber(enum.Enum):
     FATAL2 = 22
     FATAL3 = 23
     FATAL4 = 24
+
+
+_STD_TO_OTLP = {
+    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_otlp(levelno: int) -> SeverityNumber:
+    """
+    Map python log levelno as defined in https://docs.python.org/3/library/logging.html#logging-levels
+    to OTLP log severity number.
+    """
+    if levelno < 10:
+        return SeverityNumber.UNSPECIFIED
+    if levelno > 53:
+        return SeverityNumber.FATAL4
+    return _STD_TO_OTLP[levelno]

opentelemetry-sdk/tests/logs/test_handler.py

@@ -0,0 +1,84 @@
+# 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 unittest
+from unittest.mock import Mock
+
+from opentelemetry.sdk import trace
+from opentelemetry.sdk.logs import LogEmitter, OTLPHandler
+from opentelemetry.sdk.logs.severity import SeverityNumber
+from opentelemetry.trace import INVALID_SPAN_CONTEXT
+
+
+def get_logger(level=logging.NOTSET, log_emitter=None):
+    logger = logging.getLogger(__name__)
+    handler = OTLPHandler(level=level, log_emitter=log_emitter)
+    logger.addHandler(handler)
+    return logger
+
+
+class TestOTLPHandler(unittest.TestCase):
+    def test_handler_default_log_level(self):
+        emitter_mock = Mock(spec=LogEmitter)
+        logger = get_logger(log_emitter=emitter_mock)
+        # Make sure debug messages are ignored by default
+        logger.debug("Debug message")
+        self.assertEqual(emitter_mock.emit.call_count, 0)
+        # Assert emit gets called for warning message
+        logger.warning("Wanrning message")
+        self.assertEqual(emitter_mock.emit.call_count, 1)
+
+    def test_handler_custom_log_level(self):
+        emitter_mock = Mock(spec=LogEmitter)
+        logger = get_logger(level=logging.ERROR, log_emitter=emitter_mock)
+        logger.warning("Warning message test custom log level")
+        # Make sure any log with level < ERROR is ignored
+        self.assertEqual(emitter_mock.emit.call_count, 0)
+        logger.error("Mumbai, we have a major problem")
+        logger.critical("No Time For Caution")
+        self.assertEqual(emitter_mock.emit.call_count, 2)
+
+    def test_log_record_no_span_context(self):
+        emitter_mock = Mock(spec=LogEmitter)
+        logger = get_logger(log_emitter=emitter_mock)
+        # Assert emit gets called for warning message
+        logger.warning("Wanrning message")
+        args, _ = emitter_mock.emit.call_args_list[0]
+        log_record = args[0]
+
+        self.assertIsNotNone(log_record)
+        self.assertEqual(log_record.trace_id, INVALID_SPAN_CONTEXT.trace_id)
+        self.assertEqual(log_record.span_id, INVALID_SPAN_CONTEXT.span_id)
+        self.assertEqual(
+            log_record.trace_flags, INVALID_SPAN_CONTEXT.trace_flags
+        )
+
+    def test_log_record_trace_correlation(self):
+        emitter_mock = Mock(spec=LogEmitter)
+        logger = get_logger(log_emitter=emitter_mock)
+
+        tracer = trace.TracerProvider().get_tracer(__name__)
+        with tracer.start_as_current_span("test") as span:
+            logger.critical("Critical message within span")
+
+            args, _ = emitter_mock.emit.call_args_list[0]
+            log_record = args[0]
+            self.assertEqual(log_record.body, "Critical message within span")
+            self.assertEqual(log_record.severity_text, "CRITICAL")
+            self.assertEqual(log_record.severity_number, SeverityNumber.FATAL)
+            span_context = span.get_span_context()
+            self.assertEqual(log_record.trace_id, span_context.trace_id)
+            self.assertEqual(log_record.span_id, span_context.span_id)
+            self.assertEqual(log_record.trace_flags, span_context.trace_flags)