Library leads to Vary: Cookie header set

[amureki]

Greetings,

thank you for the lovely package! After checking current get_log_message, I am seeing that we will always try to grab a user attribute (and fall back to user.pk or user.id if no custom attribute was set).

And there is an interesting side effect coming from that fact:

• request.user is a lazy object until we start touching it
• the moment we access it, Django uses the session to verify that user is associated or returns AnonymousUser instance
• the moment we access a session, SessionMiddleware sets vary cookie to the headers

This logic means that even if we serve some simple static request that is not doing anything with the user instance - django-log-request-id middleware will still lead to vary cookie be set.

So, in short, that means, that logging library is changing response headers, which is an arguable behaviour.

I'd love to get your opinion on this first and then, if valid, continue discussion with possible mitigation options and improvements we could make.

Best, Rust

[codingjoe]

I agree with the sentiment. It's probably not and intended and certainly not an expeced side effect to inject a header when installing a log library.

Maybe it doesn't even make sense to log a user id, if the user wasn't touched and didn't matter for the response.

In any case, there should be an option do disable this behavior all together, like changing the setting to false or none.

[RealOrangeOne]

It looks like there's a LOG_USER_ATTRIBUTE setting to change what attribute is logged. Perhaps if this is explicitly set to False or None, logging of the user attribute is skipped. That way the user doesn't need to be retrieved, and so there's no Vary header.

This does have the downside of disabling the user logging for all views, rather just non-authed views.

Presumably you have the need for a session, but not full user authentication? This does feel like a fairly niche case.

[amureki]

@RealOrangeOne thanks for the reply!

Changing LOG_USER_ATTRIBUTE behaviour might improve here, true.

I can imagine something like this:

from django.contrib.auth.models import AnonymousUser

def get_log_message(self, request, response):
    message = 'method=%s path=%s status=%s' % (request.method, request.path, response.status_code)

    user = getattr(request, 'user', None)
    # if there is no user, or it is anonymous, instead of touching session we directly return message
    if not user or type(user) == AnonymousUser:
        return message

    # `LOG_USER_ATTRIBUTE_SETTING` accepts False/None to skip setting attribute
    #  but falls back to 'pk' if value is not set
    user_attribute = getattr(settings, 'LOG_USER_ATTRIBUTE_SETTING', 'pk')
    if user_attribute:
        user_id = getattr(user, user_attribute, None) or getattr(user, 'id', None)
        message += ' user=' + str(user_id)
    return message

Two changes here compared to the original logic:

• we are checking for the user type before accessing the session, if it is anonymous - we ignore user_id, cookie won't be set (all non-authenticated requests)
• we allow LOG_USER_ATTRIBUTE to accept False/None, so library users can completely opt out from user_id logging

What do you think?

[RealOrangeOne]

From what you mentioned above, the AnonymousUser check will still touch the session, as request.user needs to be populated from the session, which involves reading from it.

As for the rest of the change, IMO I think that makes sense. I'm sure the specifics could be nailed down with a PR.

[amureki]

@RealOrangeOne thanks for the valid note!

I added PR attempting to fix this: https://github.com/dabapps/django-log-request-id/pull/65

Would be happy to get feedback on everything: logic, naming, styling (as I am not familiar with this codebase yet).

[j4mie]

Hello! Thanks fort this issue and the PR. Just to let you know I'm not ignoring this, just very busy currently! I'll get to it when I can.