Use LogRecord.getMessage to get OTLP body

[pR0Ps]

Description

This improves compatibility with logging libraries that use logging.setLogRecordFactory() or patching to customize the message formatting of the created LogRecords. It does this by using the processed LogRecord's getMessage() method to get the body text instead of using record.msg % record.args.

Also adds "getMessage" to the list of reserved attributes so if the customization is done by patching the getMessage function on the LogRecord directly (instead of using a subclass), it's not accidentally treated as an attribute.

Related to: #3343

Type of change

• Bug fix (non-breaking change which fixes an issue)

How Has This Been Tested?

I've tested this change using the bracelogger library, which implements custom formatting by patching getMessage(). I made sure that logs produced from both bracelogger and the stdlib produced correct OTLP logs.

To verify:
myapp.py

from logging import getLogger
from bracelogger import get_logger  # pip install bracelogger

l = getLogger("normal")
l.error("Normal formatting: %s", "works")

bl = get_logger("custom")
bl.error("Custom formatting: {}", "works")

OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED=true opentelemetry-instrument --logs_exporter console python myapp.py

Produces:

{
    "body": "Normal formatting: works",
    "severity_number": "<SeverityNumber.ERROR: 17>",
    "severity_text": "ERROR",
    "attributes": {
        "otelSpanID": "0",
        "otelTraceID": "0",
        "otelTraceSampled": false,
        "otelServiceName": "unknown_service",
        "code.filepath": "code.filepath": "[REDACTED]/myapp.py",
        "code.function": "<module>",
        "code.lineno": 5
    },
    "dropped_attributes": 0,
    "timestamp": "2024-10-09T14:36:24.216596Z",
    "observed_timestamp": "2024-10-09T14:36:24.216714Z",
    "trace_id": "0x00000000000000000000000000000000",
    "span_id": "0x0000000000000000",
    "trace_flags": 0,
    "resource": {
        "attributes": {
            "telemetry.sdk.language": "python",
            "telemetry.sdk.name": "opentelemetry",
            "telemetry.sdk.version": "1.27.0",
            "telemetry.auto.version": "0.48b0",
            "service.name": "unknown_service"
        },
        "schema_url": ""
    }
}
{
    "body": "Custom formatting: works",
    "severity_number": "<SeverityNumber.ERROR: 17>",
    "severity_text": "ERROR",
    "attributes": {
        "otelSpanID": "0",
        "otelTraceID": "0",
        "otelTraceSampled": false,
        "otelServiceName": "unknown_service",
        "code.filepath": "[REDACTED]/myapp.py",
        "code.function": "<module>",
        "code.lineno": 8
    },
    "dropped_attributes": 0,
    "timestamp": "2024-10-09T14:36:24.216813Z",
    "observed_timestamp": "2024-10-09T14:36:24.216838Z",
    "trace_id": "0x00000000000000000000000000000000",
    "span_id": "0x0000000000000000",
    "trace_flags": 0,
    "resource": {
        "attributes": {
            "telemetry.sdk.language": "python",
            "telemetry.sdk.name": "opentelemetry",
            "telemetry.sdk.version": "1.27.0",
            "telemetry.auto.version": "0.48b0",
            "service.name": "unknown_service"
        },
        "schema_url": ""
    }
}

Previously the same command would cause the error:

Traceback (most recent call last):
  File "[REDACTED]/myapp.py", line 8, in <module>
    bl.error("Custom formatting: {}", "works")
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 1568, in error
    self._log(ERROR, msg, args, **kwargs)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 1684, in _log
    self.handle(record)
  File "[REDACTED]/bracelogger.py", line 42, in handle
    return fcn(record)
           ^^^^^^^^^^^
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 1700, in handle
    self.callHandlers(record)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 1762, in callHandlers
    hdlr.handle(record)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/logging/__init__.py", line 1028, in handle
    self.emit(record)
  File "[REDACTED]/opentelemetry/sdk/_logs/_internal/__init__.py", line 578, in emit
    self._logger.emit(self._translate(record))
                      ^^^^^^^^^^^^^^^^^^^^^^^
  File "[REDACTED]/opentelemetry/sdk/_logs/_internal/__init__.py", line 548, in _translate
    body = record.msg % record.args
           ~~~~~~~~~~~^~~~~~~~~~~~~
TypeError: not all arguments converted during string formatting

Does This PR Require a Contrib Repo Change?

• Yes. - Link to PR:
• No.

Checklist:

• Followed the style guidelines of this project
• Changelogs have been updated
• Unit tests have been added
• Documentation has been updated

[linux-foundation-easycla]

The committers listed above are authorized under a signed CLA.

• ✅ login: pR0Ps / name: Carey Metcalfe (9facfd2, 7e68bc9, 1a2d984)

[pR0Ps]

Some extra notes:

In my opinion, the most compatible thing to do would be to always call body = record.getMessage(), regardless of if record.msg is a string or not. However, this would just be reverting #3343 which explicitly added that behavior (including tests for it) and was merged. I am happy to make that change if requested though.

Note that this isn't just an issue with the bracelogger package I mentioned above. Doing a search on GitHub for language:python "record.getMessage =" yields quite a few results where a custom getMessage is patched onto log records.

Those search results also include cases where getMessage is used not to customize the formatting, but as a place to hook to add more information to the record itself - this is why I mentioned above that it would be more compatible to always call getMessage() - it's expected that it's always called and the current behavior of only calling it in some cases breaks that expectation.

[xrmx]

@pR0Ps Please add a changelog entry

[pR0Ps]

@xrmx done! Let me know if you want me to change it in some way

[lzchen]

@pR0Ps

In my opinion, the most compatible thing to do would be to always call body = record.getMessage(), regardless of if record.msg is a string or not.

I'm curious as why you think this is the case? According to getMessage documentation:

If the user-supplied message argument to the logging call is not a string, str() is called on it to convert it to a string. This allows use of user-defined classes as messages, whose str method can return the actual format string to be used.

I'm not sure if this behavior that we want since we want to preserve the original Any type of the body message and exporters may not be expecting a stringified version of the body.

[lzchen]

Question about getMessage

[pR0Ps]

That documentation states that using a user-defined class as the message can define a custom format string, not a custom message. This means that the expected behavior if you call logging.error(MyCustomClass(), arg1) is that the message is arg1 formatted into str(MyCustomClass()).

More concretely, this means that the following two log messages should both be just "test" (which they are without being instrumented by open telemetry):

class CustomFormat:
    def __str__(self):
        return "%s"

logging.error(CustomFormat(), "test")
logging.error("%s", "test")

As currently written, open telemetry sets body=CustomFormat() for the first (dropping "test" entirely and causing serialization to fail since the CustomFormat instance cannot be serialized), and body="test" for the second. By always using body=record.getMessage() instead of only when isinstance(record.msg, str) and record.args:, the body is (correctly, IMO) set to "test" in both cases.

---

I'm not sure if this behavior that we want since we want to preserve the original Any type of the body message and exporters may not be expecting a stringified version of the body.

I don't know if there's a good way around that since a log's message is basically always expected to be a string due to the fact that the logging functions expect to be provided a string to format the data into in order to produce the message. From logging.Logger.debug(msg, *args, **kwargs) docs:

The msg is the message format string, and the args are the arguments which are merged into msg using the string formatting operator. [...] No % formatting operation is performed on msg when no args are supplied.

Since record.getMessage() is always called by the logging system to compute the log's "message" from the format string and args, this is why I mentioned I thought that always using it to compute the body would be the most compatible option.

However, since the docs also mention that no formatting is performed when no args are provided, the following might be a good middle-ground where it still dumps the record.msg without stringifying it, but only in the case where there are no arguments provided.

if record.args:
    body = record.getMessage()
else:
    body = record.msg

This would still break in the case of using a user-defined class as a format string with no args (ie. logging.error(CustomFormat())), but I would imagine that isn't very likely to happen.

[lzchen]

However, since the docs also mention that no formatting is performed when no args are provided, the following might be a good middle-ground where it still dumps the record.msg without stringifying it, but only in the case where there are no arguments provided.

I think this is a good middle ground. We should preserve original body as much as possible unless if it defies what users "commonly" expect out of Python logging library (formatting is expected to return string).

This would still break in the case of using a user-defined class as a format string with no args (ie. logging.error(CustomFormat())), but I would imagine that isn't very likely to happen.

Could you be more specific about what would break? Are you referring to the otlp exporter encoding types that are not supported? If so, I believe that this would be expected behavior to error out since it is technically not following the typing of AnyValue of log body/otlp log body as defined by the spec. The only thing that we probably should change is to catch the exception and log a warning instead (since we do not want to crash the application during runtime for a misuse of the sdk).

[pR0Ps]

I think this is a good middle ground. We should preserve original body as much as possible unless if it defies what users "commonly" expect out of Python logging library (formatting is expected to return string).

I don't know for sure, but I would hope that most users would expect that the logs are going to be strings. Only if you are using the logging system improperly is the record.msg going to be an object to save as the body. record.msg is documented and implemented to be either a format string or an object that is stringified to a format string. The record.args and all the extra attributes are where the actual objects are meant to be. It just happens to work if you only log out a single object.

As an example of this, consider:

>>> logging.error(["contains", "a", "%s"])
ERROR:root:['contains', 'a', '%s']

What's actually happening is the first arg is stringified to a format string due to:

If the user-supplied message argument to the logging call is not a string, str() is called on it to convert it to a string.

Then, the rule:

No % formatting operation is performed on msg when no args are supplied

is applied so nothing else happens to it, resulting in a message of "['contains', 'a', '%s']"

You can see this more clearly if you slightly modify the example to add an argument:

>>> logging.error(["contains", "a", "%s"], "string")
ERROR:root:['contains', 'a', 'string']

["contains", "a", "%s"] is stringified to "['contains', 'a', '%s']", then "['contains', 'a', '%s']" % "string" is run to produce the result.

It's definitely the case that there's code that just dumps objects into logging calls without a format string (ie. presumably the author of #3343 does this) which is why I proposed the middle-ground solution I mentioned above, but I don't think it's an intended way to use the logging system.

---

Could you be more specific about what would break?

The following code will break with the middle-ground solution I mentioned above:

class CustomFormat:
    def __str__(self):
        return "%s"

logging.error(CustomFormat())

This is because it would set body=CustomFormat() due to there not being any args. Then, when the record is serialized to JSON, attempting to serialize the CustomFormat object would raise an exception. And, to be clear, this is a perfectly valid thing to do according to the Python logging docs. It's not very useful, since it would just log out the message "%s", but it is valid.

---

Honestly, given all the nuance, the potential for breakage, and the semi-random "this body is an object because there are no args, this body is a formatted string because there were args" aspects of the above, personally I would avoid trying to be fancy and just revert #3343 . It's supporting a use-case that, in my reading of the docs, just isn't valid. According to the docs, the msg should be a format string and objects to display should be provided in record.args. Providing an object as the format string may happen to work, but IMO it's not intended behavior and therefore shouldn't be explicitly supported.

[pR0Ps]

@lzchen I have applied the middle ground proposal I mentioned above including a comment explaining it and link back to this PR. I would still recommend reverting #3343 instead, but if it's a requirement that the use-case of not stringifying objects passed via logging.error(obj) is supported then I believe this is the next-best option.

EDIT: I've pushed a commit to another branch that implements the "always call record.getMessage()" implementation. It can be viewed here: main...pR0Ps:opentelemetry-python:bugfix/bracelogger-compatibility-alt . I can merge it into this PR if you're ok with it.

[lzchen]

@pR0Ps

Hmm, this might need a longer discussion. Would you be able to join the weekly Python SIG meeting and bring up this topic? We meet every Thursday 9am PST.

[pR0Ps]

@lzchen I've sent you an email to follow up

[lzchen]

@pR0Ps

I'm not sure what email you've sent it to and I don't usually respond to emails sent directly. Feel free to ping me on slack if you'd like to discuss further. It is also preferred to bring this topic up in the Python SIG, as there are other people who might have opinions and useful perspectives on this.

[lzchen]

@pR0Ps

Thanks for the contribution. Would it be possible to add some tests?

[pR0Ps]

@lzchen Added a test for the version that only skips calling record.getMessage if record.msg is a non-string and there are no record.args.

I'll submit the version that always calls record.getMessage in a different PR so the discussion on that can continue without blocking this improvement.