Title: logging messages are needlessly reformatted for every handler
Type: enhancement Stage: resolved
Components: Library (Lib) Versions: Python 3.10
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: Nosy List: SpecLad, vinay.sajip
Priority: normal Keywords:

Created on 2021-10-13 22:39 by SpecLad, last changed 2021-10-15 23:59 by vinay.sajip. This issue is now closed.

Messages (4)
msg403879 - (view) Author: Роман Донченко (SpecLad) * Date: 2021-10-13 22:39
Consider this code:

import logging

class MyLogRecord(logging.LogRecord):
    def getMessage(self):
        print("Help! I am being formatted!")
        return super().getMessage()


logger = logging.getLogger("test")

logger.error("%d", 123)

Its output is:

Help! I am being formatted!
Help! I am being formatted!

In other words, the record's `getMessage` method is called once for every handler. That seems quite unnecessary, especially since the formatted message is saved in the `message` field of the record by `Formatter.format`. `Formatter` could check whether the message has already been formatted, and if so, use the saved message.
msg404000 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2021-10-15 10:21
A developer may wish to format messages differently for different audiences (i.e. different handlers) - for example, omit stack traces. This behaviour is by design.
msg404058 - (view) Author: Роман Донченко (SpecLad) * Date: 2021-10-15 22:14
But message formatting is controlled by the record, not by the handler. The same record will always be formatted the same way (assuming that getMessage is deterministic, which seems like a fair assumption).
msg404060 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2021-10-15 23:59
Oh, I see what you mean now - I was thinking of the overall message formatted using a formatter. However, filters can still change a record's attributes and getMessage() could behave differently on different calls because of this. Changing things in this area could break existing code.
Date User Action Args
2021-10-15 23:59:54vinay.sajipsetmessages: + msg404060
2021-10-15 22:14:32SpecLadsetmessages: + msg404058
2021-10-15 10:21:07vinay.sajipsetstatus: open -> closed
resolution: not a bug
messages: + msg404000

stage: resolved
2021-10-15 00:59:49ned.deilysetnosy: + vinay.sajip
2021-10-13 22:39:47SpecLadcreate