How does logging's 'extra' argument work?

Question

I am struggling to figure out exactly how the extra argument for logging works. I have some legacy code I need to change which uses it, and the code also requires logging to stdout.

import logging

log = logging.getLogger()
handler = logging.Streamhandler(sys.stdout)
handler.setLevel("INFO")
formatter = logging.Formatter('%(asctime)s | %(name)s | %(levelname)s | %(message)s')
handler.setFormatter(formatter)
log.addHandler(handler)

log.error("fly you foos!", extra={"City": "Mordor"})

2019-10-31 16:19:04,422 | root | ERROR | fly you foos!

The above logs fly you foos! but does not do anything with the extra argument. This makes sense since the extra argument is not really being used in any way.

However according to this documentation I can change the Formatter to include the additional dictionary key 'City':

formatter = logging.Formatter('%(asctime)s | %(name)s | %(levelname)s | %(message)s | %(City)s')

2019-10-31 16:19:04,422 | root | ERROR | fly you foos! | Mordor

This gives me the correct log line I am looking for, however it also gives me a KeyError since every other place where I use log will now also require, as an argument, a dictionary which includes the key City. This is obviously infeasible since it requires changing every instance log is used, adding redundant arguments just to fit the Formatter.

I would like to know how extra is traditionally used or any nuances here that I haven't understood yet. Ideally I want to see the extra part of the exception every time without having to change the Formatter.

Answer 1

As stated by 9769953:

If you choose to use these attributes in logged messages, you need to exercise some care. In the above example, for instance, the Formatter has been set up with a format string which expects ‘clientip’ and ‘user’ in the attribute dictionary of the LogRecord. If these are missing, the message will not be logged because a string formatting exception will occur. So in this case, you always need to pass the extra dictionary with these keys.

(Source).

For your problem at hand:

however it also gives me a KeyError since every other place where I use log will now also require, as an argument, a dictionary which includes the key City

It can be very cumbersome to add the extra argument everywhere in you logging.error. Instead, you can create your own logger to allow for this extra argument City to have a default value:

import logging
import sys

class NewLogger(logging.Logger):
    # override the makeRecord method
    def makeRecord(self, *args, **kwargs):
        rv = super(NewLogger, self).makeRecord(*args, **kwargs)
        rv.__dict__["City"] = rv.__dict__.get("City", "Khazad-dum")
        return rv

log = NewLogger("foobar")
log.propagate = False
handler = logging.StreamHandler(sys.stdout)
handler.setLevel("INFO")
formatter = logging.Formatter('%(asctime)s | %(name)s | %(levelname)s | %(message)s | %(City)s')
handler.setFormatter(formatter)
log.addHandler(handler)

log.error("you shall not pass")  # should log the default value
log.error("fly you foos!", extra={"City": "Mordor"})  # should log "Mordor"

The output is:

2023-02-07 13:56:17,875 | foobar | ERROR | you shall not pass | Khazad-dum
2023-02-07 13:56:17,875 | foobar | ERROR | fly you foos! | Mordor

There are other ways to pass extra arguments to all logs with logging.Adapter and getLogRecordFactory/setLogRecordFactory. But I could not make them work for your particular use case.

---

Adapter

import logging
import sys

log = logging.getLogger("foobar")
log.propagate = False
handler = logging.StreamHandler(sys.stdout)
handler.setLevel("INFO")
formatter = logging.Formatter('%(asctime)s | %(name)s | %(levelname)s | %(message)s | %(City)s')
handler.setFormatter(formatter)
log.addHandler(handler)


log = logging.LoggerAdapter(logging.getLogger("foobar"), extra={"City": "Khazad-dum"})

log.error("you shall not pass")
log.error("fly you foos!", extra={"City": "Mordor"})

2023-02-07 14:06:02,201 | foobar | ERROR | you shall not pass | Khazad-dum
2023-02-07 14:06:02,201 | foobar | ERROR | fly you foos! | Khazad-dum

As you can see, it gives the extra argument to all your logs, but when you overwrite yours with log.error("fly you foos!", extra={"City": "Mordor"}), it does not update City with the specified value. Therefore, it is more useful for a "global" variable that you want to include inside your logs.

---

Record Factory

You can use the record factory feature of logging to add extra arguments to your log.

import logging
import sys

log = logging.getLogger("foobar")
log.propagate = False
handler = logging.StreamHandler(sys.stdout)
handler.setLevel("INFO")
formatter = logging.Formatter('%(asctime)s | %(name)s | %(levelname)s | %(message)s | %(City)s')
handler.setFormatter(formatter)
log.addHandler(handler)


old_factory = logging.getLogRecordFactory()

def record_factory(*args, **kwargs):
    record = old_factory(*args, **kwargs)  # get the unmodified record
    record.City = "Khazad-dum"
    return record

logging.setLogRecordFactory(record_factory)

log.error("you shall not pass")
log.error("fly you foos!", extra={"City": "Mordor"})

However, it fails on the second log.error:

2023-02-07 14:11:19,722 | foobar | ERROR | you shall not pass | Khazad-dum
Traceback (most recent call last):
  File "main.py", line 82, in <module>
    log.error("fly you foos!", extra={"City": "Mordor"})
  File "/home/vvvvv/.pyenv/versions/3.8.12/lib/python3.8/logging/__init__.py", line 1475, in error
    self._log(ERROR, msg, args, **kwargs)
  File "/home/vvvvv/.pyenv/versions/3.8.12/lib/python3.8/logging/__init__.py", line 1587, in _log
    record = self.makeRecord(self.name, level, fn, lno, msg, args,
  File "/home/vvvvv/.pyenv/versions/3.8.12/lib/python3.8/logging/__init__.py", line 1561, in makeRecord
    raise KeyError("Attempt to overwrite %r in LogRecord" % key)
KeyError: "Attempt to overwrite 'City' in LogRecord"

It is impossible by this way to overwrite an extra argument given by default inside the record factory.

See Why is it forbidden to override log record attributes?.