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.

Uphold

The same documentation also states "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." – Baalman

(cont) "While this might be annoying, this feature is intended for use in specialized circumstances, such as multi-threaded servers where the same code executes in many contexts, and interesting conditions which arise are dependent on this context (such as remote client IP address and authenticated user name, in the above example). In such circumstances, it is likely that specialized Formatters would be used with particular Handlers."" – Baalman

To follow up, I've used extras extensively before, and as the above docs suggest you'll have the best luck using a custom Formatter subclass (the logging docs do discuss how to subclass Formatter somewhere). This will allow you to write something more flexible, e.g. that will only append the City field to messages when the log record includes City. Or to provide a default or something like that. – Stile

In other words, any time you need more formatting logic beyond just interpolation of a single format string, you should create a custom Formatter – Stile

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?.

Easiness

I used your NewLogger class to output a user name in the LogRecord by changing this line: rv.__dict__["user"] = rv.__dict__.get("user", getpass.getuser()). Now the extra argument to each log 'posting' is no longer needed: truly extra. – Agitation