CloudWatchLogFormatter with add_log_record_attrs does not correctly format string messages

[dgilmanAIDENTIFIED]

If the add_log_record_attrs is set string messages are not formatted before being shoved into the "msg" in the CloudWatch JSON.

Here's a minimal reproduction:

import logging
import watchtower

logger = logging.getLogger("foo")
handler = watchtower.CloudWatchLogHandler()
handler.formatter.add_log_record_attrs=["levelname", "filename", "process", "thread"]
logger.addHandler(handler)
logger.critical("hello %s world %s", 5, 10)

This produces a JSON in CloudWatch like so:

{
    "msg": "hello %s world %s",
    "levelname": "CRITICAL",
    "filename": "test.py",
    "process": 9155,
    "thread": 4545472000
}

If you comment out the handler.formatter.add_log_record_attrs you get the plain string logged to CloudWatch with formatting done, e.g. just hello 5 world 10.

[riebecj]

I think this is by design, but you can swap out your own log format once CloudWatchLogHandler is instantiated like so:

class CloudWatchLogFormatter(logging.Formatter):
    def __init__(self, fmt: Optional[str] = None):
        super().__init__()
        if fmt:
            self._style._fmt = fmt
            self._style.validate()

    def format(self, record: logging.LogRecord) -> str:
        record.message = record.msg % record.args
        return self.formatMessage(record=record)

def main():
    cw_log_handler = CloudWatchLogHandler()
    cw_log_handler.setFormatter(CloudWatchLogFormatter(fmt=CLOUDWATCH_LOG_FORMATTING))

    logging.basicConfig(
        format=LOCAL_LOG_FORMATTING,
        level=logging.INFO,
        handlers=[cw_log_handler]
    )

Because I have CLOUDWATCH_LOG_FORMATTING set to "%(levelname)s - %(name)s - %(thread)d - %(message)s", it will display the logs how I want in CloudWatch.

I initially thought along your lines that it would include those log attributes in the log line similar to python's logging, but unfortunately, all it does is give you a JSON string.

[kislyuk]

Thanks for reporting and contributing. I have a possible solution in #184 but I need to think through the implications.

[WiredNerd]

I recently encountered this problem. When I looked at how Python's built in Formatter handles this, it calls self.formatMessage to create the message string. I tried this with one of my applications and it's working great.

class CloudWatchLogFormatter(logging.Formatter):
...
    def format(self, message):
        if self.add_log_record_attrs:
            msg = message.msg if isinstance(message.msg, Mapping) else {"msg": self.formatMessage(message)}
            for field in self.add_log_record_attrs:
                if field != "msg":
                    msg[field] = getattr(message, field)  # type: ignore
            message.msg = msg
        if isinstance(message.msg, Mapping):
            return json.dumps(message.msg, default=self.json_serialize_default)
        return super().format(message)

[alexminza]

It is ironic because add_log_record_attrs is the recommended way to enable JSON logging:

https://kislyuk.github.io/watchtower/#watchtower.CloudWatchLogFormatter

If the optional add_log_record_attrs attribute or keyword argument is set, it enables the forwarding of specified LogRecord attributes with the message. In this mode, if the message is not already a dictionary, it is converted to one with the original message under the msg key:

Had to come up with a bit of a not very straightforward but working solution:
Include the message field in the add_log_record_attrs

cloudwatch_handler.formatter.add_log_record_attrs=["name", "levelname", "filename", "lineno", "funcName", "message"]