Avoid using log filter to modify/enrich log record

[faph]

The current implementation provides log filter classes which can be used to enrich the log records with correlation IDs. This is a surprising use of a filter since it has a side effect and modifies a log record. For example, when attaching the filter to one handler, another handler may see the modified log record.

According to the documentation (just below https://docs.python.org/3/library/logging.html?highlight=logrecord#logging.LogRecord.getMessage), the intended pattern for custom log record generation is to use a modified log record factory function like this:

old_factory = logging.getLogRecordFactory()

def record_factory(*args, **kwargs):
    record = old_factory(*args, **kwargs)
    record.custom_attribute = 0xdecafbad
    return record

logging.setLogRecordFactory(record_factory)

The only annoying thing here is that this one-off setting of the factory cannot be done using logging.config.

Short of asking app developers to bootstrap the record factory, manually, there may be an alternative whereby the ASGI middleware could be responsible for this. When using a class-based middleware implementation, the middleware's __init__() constructor may be able to set the log record factory?

[faph]

The bit I havent got my head around is the application's startup sequence. What happens to log messages emitted before the middleware is instantiated? Presumably such log records would not have correlation_id attributes? That would fail %(correlation_id)s log message interpolation...

[sondrelg]

To answer the last post first, the log will output None in place of the correlation ID when it hasn't yet been set. Like I just mentioned in #35, this could be a good reason to add this middleware as early as possible (it has been a while since I tested this, but at least in Django apps this is the behaviour, and I think Starlette is the same).

I'm not sure I see why a side-effect is an issue here. Could you elaborate on why you think it's problematic?

[faph]

The main reason why it might be problematic in some cases if you attach the filter to one handler (eg std out) then suddenly another handler (eg JSON file) may also see the modified record and output unexpected log record attributes. I am mentioning a JSON formatter here as they typically output all attributes.

Secondly, the log filter API is a filtering thing. Modifying the log record is unexpected from an app developer’s perspective. While it is possible to modify the record the question is whether it is a good thing and might break other aspects of the logging API. The above example is possibly only one such example.

It does feel to me that the standard library’s custom log record creation API is possibly under developed. Or at least with regards to logging.config.

[faph]

I guess I’m just thinking out loud whether we can do better than the pragmatic approach of wiring up filters like this…

[sondrelg]

I can see how using setLogRecordFactory might be more appropriate than using filters to set the correlation ID property, but I think you end up with a modified log record in both cases.

Let's say we have a log configuration with a json-log formatter and a basic console formatter like this:

The way I see it, it doesn't matter if you mutate the record in a filter or by changing the default factory. Both alter the global record and would equally affect both formatters, wouldn't they?

I tend to agree that a filter seems a little odd after reading about the factories, but still not sure I understand how they differ in practice. Maybe I'm missing something obvious 🙂

[faph]

I agree, in practice the end result is the same.

From an app developer's UX perspective though, we should not need to specify logging filters, just to make an attribute available on the log record. Hence I was thinking how the ASGI middleware might be able to hook into log record creation such that wiring up the middleware would be all that is required (plus maybe log formatting, depending on the formatter).

[sondrelg]

Yeah definitely open to suggestions here. Would be cool if the creation of the record attribute could be done by us, and the filter could be kept for formatting purposes.

[faph]

Turns out I was wrong. The docs explicitly allow for filters modifying records: https://docs.python.org/3.10/howto/logging-cookbook.html#using-filters-to-impart-contextual-information

[faph]

See also here: https://docs.python.org/3/library/logging.html#filter-objects

Obviously changing the LogRecord needs to be done with some care, but it does allow the injection of contextual information into logs

[faph]

I will still find some time to play with the log record factory. Just to see if we can simplify the log setup.

[sondrelg]

Really appreciate all the digging you've done here, and happy to review suggestions for improvement, but in the meantime I'll close this 🙂