Add support for log formatting

Author: jeremydvoss

CHANGELOG.md

@@ -7,6 +7,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## Unreleased
 
+- sdk: Add support for log formatting
+  ([#4137](https://github.com/open-telemetry/opentelemetry-python/pull/4166))
 - Implementation of Events API
   ([#4054](https://github.com/open-telemetry/opentelemetry-python/pull/4054))
 - Make log sdk add `exception.message` to logRecord for exceptions whose argument

opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py

@@ -506,48 +506,14 @@ def _translate(self, record: logging.LogRecord) -> LogRecord:
         observered_timestamp = time_ns()
         span_context = get_current_span().get_span_context()
         attributes = self._get_attributes(record)
-        # This comment is taken from GanyedeNil's PR #3343, I have redacted it
-        # slightly for clarity:
-        # According to the definition of the Body field type in the
-        # OTel 1.22.0 Logs Data Model article, the Body field should be of
-        # type 'any' and should not use the str method to directly translate
-        # the msg. This is because str only converts non-text types into a
-        # human-readable form, rather than a standard format, which leads to
-        # the need for additional operations when collected through a log
-        # collector.
-        # Considering that he Body field should be of type 'any' and should not
-        # use the str method but record.msg is also a string type, then the
-        # difference is just the self.args formatting?
-        # The primary consideration depends on the ultimate purpose of the log.
-        # Converting the default log directly into a string is acceptable as it
-        # will be required to be presented in a more readable format. However,
-        # this approach might not be as "standard" when hoping to aggregate
-        # logs and perform subsequent data analysis. In the context of log
-        # extraction, it would be more appropriate for the msg to be
-        # converted into JSON format or remain unchanged, as it will eventually
-        # be transformed into JSON. If the final output JSON data contains a
-        # structure that appears similar to JSON but is not, it may confuse
-        # users. This is particularly true for operation and maintenance
-        # personnel who need to deal with log data in various languages.
-        # Where is the JSON converting occur? and what about when the msg
-        # represents something else but JSON, the expected behavior change?
-        # For the ConsoleLogExporter, it performs the to_json operation in
-        # opentelemetry.sdk._logs._internal.export.ConsoleLogExporter.__init__,
-        # so it can handle any type of input without problems. As for the
-        # OTLPLogExporter, it also handles any type of input encoding in
-        # _encode_log located in
-        # opentelemetry.exporter.otlp.proto.common._internal._log_encoder.
-        # Therefore, no extra operation is needed to support this change.
-        # The only thing to consider is the users who have already been using
-        # this SDK. If they upgrade the SDK after this change, they will need
-        # to readjust their logging collection rules to adapt to the latest
-        # output format. Therefore, this change is considered a breaking
-        # change and needs to be upgraded at an appropriate time.
         severity_number = std_to_otel(record.levelno)
-        if isinstance(record.msg, str) and record.args:
-            body = record.msg % record.args
+        if self.formatter:
+            body = self.format(record)
         else:
-            body = record.msg
+            if isinstance(record.msg, str) and record.args:
+                body = record.msg % record.args
+            else:
+                body = record.msg
 
         # 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.

opentelemetry-sdk/tests/logs/test_export.py

@@ -207,6 +207,45 @@ def test_simple_log_record_processor_different_msg_types(self):
         ]
         self.assertEqual(expected, emitted)
 
+    def test_simple_log_record_processor_different_msg_types_with_formatter(self):
+        self.maxDiff = None
+        exporter = InMemoryLogExporter()
+        log_record_processor = BatchLogRecordProcessor(exporter)
+
+        provider = LoggerProvider()
+        provider.add_log_record_processor(log_record_processor)
+
+        logger = logging.getLogger("different_msg_types")
+        handler = LoggingHandler(logger_provider=provider)
+        handler.setFormatter(logging.Formatter(
+            "%(name)s - %(levelname)s - %(message)s"
+        ))
+        logger.addHandler(handler)
+
+        logger.warning("warning message: %s", "possible upcoming heatwave")
+        logger.error("Very high rise in temperatures across the globe")
+        logger.critical("Temperature hits high 420 C in Hyderabad")
+        logger.warning(["list", "of", "strings"])
+        logger.error({"key": "value"})
+        log_record_processor.shutdown()
+
+        finished_logs = exporter.get_finished_logs()
+        expected = [
+            ("different_msg_types - WARNING - warning message: possible upcoming heatwave", "WARN"),
+            ("different_msg_types - ERROR - Very high rise in temperatures across the globe", "ERROR"),
+            (
+                "different_msg_types - CRITICAL - Temperature hits high 420 C in Hyderabad",
+                "CRITICAL",
+            ),
+            ("different_msg_types - WARNING - ['list', 'of', 'strings']", "WARN"),
+            ("different_msg_types - ERROR - {'key': 'value'}", "ERROR"),
+        ]
+        emitted = [
+            (item.log_record.body, item.log_record.severity_text)
+            for item in finished_logs
+        ]
+        self.assertEqual(expected, emitted)
+
 
 class TestBatchLogRecordProcessor(ConcurrencyTestBase):
     def test_emit_call_log_record(self):

opentelemetry-sdk/tests/logs/test_handler.py

@@ -13,7 +13,7 @@
 # limitations under the License.
 import logging
 import unittest
-from unittest.mock import Mock
+from unittest.mock import Mock, MagicMock
 
 from opentelemetry._logs import NoOpLoggerProvider, SeverityNumber
 from opentelemetry._logs import get_logger as APIGetLogger
@@ -242,13 +242,53 @@ def test_log_record_trace_correlation(self):
             self.assertEqual(log_record.span_id, span_context.span_id)
             self.assertEqual(log_record.trace_flags, span_context.trace_flags)
 
+    def test_warning_without_formatter(self):
+        processor, logger = set_up_test_logging(logging.WARNING)
+        logger.warning("Test message")
+
+        log_record = processor.get_log_record(0)
+        self.assertEqual(log_record.body, "Test message")
+
+    def test_exception_without_formatter(self):
+        processor, logger = set_up_test_logging(logging.WARNING)
+        logger.exception("Test exception")
+
+        log_record = processor.get_log_record(0)
+        self.assertEqual(log_record.body, "Test exception")
+
+    def test_warning_with_formatter(self):
+        processor, logger = set_up_test_logging(
+            logging.WARNING,
+            formatter=logging.Formatter(
+                "%(name)s - %(levelname)s - %(message)s"
+            ),
+        )
+        logger.warning("Test message")
+
+        log_record = processor.get_log_record(0)
+        self.assertEqual(log_record.body, "foo - WARNING - Test message")
+
+    def test_log_body_is_always_string_with_formatter(self):
+        processor, logger = set_up_test_logging(
+            logging.WARNING,
+            formatter=logging.Formatter(
+                "%(name)s - %(levelname)s - %(message)s"
+            ),
+        )
+        logger.warning(["something", "of", "note"])
+
+        log_record = processor.get_log_record(0)
+        self.assertIsInstance(log_record.body, str)
+
 
-def set_up_test_logging(level):
+def set_up_test_logging(level, formatter=None):
     logger_provider = LoggerProvider()
     processor = FakeProcessor()
     logger_provider.add_log_record_processor(processor)
     logger = logging.getLogger("foo")
     handler = LoggingHandler(level=level, logger_provider=logger_provider)
+    if formatter:
+        handler.setFormatter(formatter)
     logger.addHandler(handler)
     return processor, logger