2

I have a custom formatter in my python Flask application, which I've added to the root logger:

logger = logging.getLogger()
logger.setLevel(logging.INFO)

handler = logging.StreamHandler()
handler.setLevel(logging.INFO)

formatter = CustomLoggingFormatter()
handler.setFormatter(formatter)

logger.addHandler(handler)

This works perfectly fine when I want to log something (logger.info()...), but I have an issue with the logs from libraries, e.g. uwsgi.

Here is an example of a log-message:

{"@timestamp": "2017-09-25T06:57:45.373Z", "level": "INFO", "message": " * Running on %s://%s:%d/ %s"}

I thought perhaps something was wrong with my formatter, but when I log the LogRecord which my CustomLoggingFormatter receivs, it looks like this for the line above:

LogRecord: werkzeug, 20, <...>/lib/python3.5/site-packages/werkzeug/_internal.py, 87, " * Running on %s://%s:%d/ %s"

Here is my CustomLoggingFormatter:

class CustomLoggingFormatter(Formatter):
    data = {}

    def __init__(self):
        super(CustomLoggingFormatter, self).__init__()

    def format(self, record):
        print(record)
        input_data = {}
        input_data['@timestamp'] = datetime.utcnow().isoformat()[:-3] + 'Z'
        input_data['level'] = record.levelname
        if record.msg:
            input_data['message'] = record.msg

        input_data.update(self.data)
        return json.dumps(input_data)

For my formatter to work, it seems the string formatting must be resolved first, but for several libraries that doesn't happen. Anyone who knows how to fix this issue?

4
  • Please do show your custom code. Formatter.format() always has to handle a LogRecord instance; the default implementation calls Formatter.formatMessage() to handle the actual formatting (which typically uses vars(record) as a dictionary).
    – Martijn Pieters
    Sep 25, 2017 at 7:15
  • Added my CustomLoggingFormatter :)
    – user16655
    Sep 25, 2017 at 7:17
  • Since the formatter implementation changed a bit between Python versions, what version of Python are you running?
    – Martijn Pieters
    Sep 25, 2017 at 7:19
  • It's using python 3.5 :)
    – user16655
    Sep 25, 2017 at 7:20

1 Answer 1

3

You need to always call record.getMessage(); it takes the value of record.msg and applies formatting to that. The default implementation of Formatter.format() assigns the result to record.message for interpolation into the final string. Do you in your code too:

def format(self, record):
    print(record)
    record.message = record.getMessage()
    input_data = {}
    input_data['@timestamp'] = datetime.utcnow().isoformat()[:-3] + 'Z'
    input_data['level'] = record.levelname

    if record.message:
        input_data['message'] = record.message

    input_data.update(self.data)
    return json.dumps(input_data)
1
  • Worked like a charm! Thanks a lot :)
    – user16655
    Sep 25, 2017 at 7:27

Your Answer

Reminder: Answers generated by Artificial Intelligence tools are not allowed on Stack Overflow. Learn more

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Not the answer you're looking for? Browse other questions tagged or ask your own question.