Couple of minor improvements

[tlinhart]

Hi @sondrelg I wonder if you would be willing to accept another two minor improvements.

The default value for the correlation ID is None which is perfectly fine. However, None also appears in logs when there is no correlation ID set. People might want to alter this behaviour and log something more neutral as None looks too Pythonic. E.g. some symbol like - (which is what for example nginx logs when variable is not defined). This could be achieved by introducing a new parameter to the log filter constructor which would be then supplied as the default value to the call to correlation_id.get(). The parameter could be named for example default_value (makes sense in the context of a log filter) or none_replacement.

The second thing relates to the case when incoming correlation ID does not pass validations and is thus replaced with a generated value. It logs a warning which reads

Generated new request ID (xxxxx), since request header value failed validation

but xxxxx contains the original header value, not the newly generated one. Given the wording of the warning, it's a bit confusing as one would expect that the log would contain the newly generated value. I'd either suggest to replace the behaviour and log the newly generated value, or change the warning to

Generated new request ID (xxxxx-new), since request header value (xxxxx-original) failed validation

The later approach might be a better solution as it would allow you to correlate both IDs, the original (which might come from and be logged by a downstream service) and the new one (which might be propagated to and logged by an upstream service).

What do you think?

[sondrelg]

So for the first suggestion, you are proposing this change, correct?

class CorrelationIdFilter(Filter):
    """Logging filter to attached correlation IDs to log records"""

-    def __init__(self, name: str = '', uuid_length: Optional[int] = None):
+    def __init__(self, name: str = '', uuid_length: Optional[int] = None, default_value: Optional[str] = None):
        super().__init__(name=name)
        self.uuid_length = uuid_length
+     self.default_value = default_value

    def filter(self, record: 'LogRecord') -> bool:
-        cid = correlation_id.get()
+        cid = correlation_id.get() or default_value
        record.correlation_id = _trim_string(cid, self.uuid_length)
        return True

That seems reasonable 👍

For the second, perhaps logging the logger, without change, after we call correlation_id.set(id_value) would make most sense? That way the request is aggregated with remaining request when queried by the new request ID, but the log still only contains the strictly necessary information. Do you see any flaws in that approach?

[tlinhart]

As for the first suggestion, yeah, that's the idea. I just vote for using

cid = correlation_id.get(default_value)

instead of

cid = correlation_id.get() or default_value

It's IMHO semantically cleaner (as per the docs) and also accounts for the case should you ever change the default value of the context variable from None to e.g. an empty string. The same change would be done to both log filters, i.e. to CeleryTracingIdsFilter as well, just to be complete. I'll prepare a PR for this one if you agree.

As for the second suggestion, my point was two-fold. First, as per the current wording it's a bit confusing when after stating about a new request ID you specify the old one (in parentheses). That could be solved by your suggestion, if I understand it correctly. Or, the warning could be rephrased to e.g.

Generated new request ID, since request header value (xxxxx) failed validation

That would still log only the original header but in a more understandable way. This all just really depends on what your goal really was – log the original value or the newly generated one? My second suggestion was to log both, but as per the comment from @JonasKs there can be a security risk.

[sondrelg]

Both sound good to me, pending input from Jonas 🙂

[JonasKs]

First request: 👍 I agree 😊

Second request: I don't agree, not because it's not a nice idea, but because of security concerns. Sonarqube, bandit etc. will fail if this is implemented, and we've seen the catastrophic impact usage of headers, without parsing can have with log4j. I specifically removed it in Django-GUID due to this: snok/django-guid#69

If you really want this, I suggest creating a custom validator where you log the input, I don't think it should be the default of the library.

[JonasKs]

Overflows are the second most common vulnerability in Python, and log interpolation isn't safe from it.

Log being aggregated to other systems also face the same issues, as @tlinhart pointed out.

[tlinhart]

I get your point @JonasKs. To be true, I've never thought about this being a security risk until now. And as the whole or at least a major point of this middleware is to be able to log the request ID coming from an input HTTP request header, I now I fully appreciate the existence of validator and the default checking for an UUID value.

[tlinhart]

Anyway, at the moment, the original header value is being logged if it doesn't pass the validations. Which I assume is exactly the case of a potential security issue. How about that? As pointed out above, I see three options where the third one is IMHO a good compromise. The newly generated header value is something you can control (thus ensure validity) and gives you at least something at hand when correlating the logged requests.

[JonasKs]

Sounds like a good solution to me. 😊

[JonasKs]

So like sql injection, but with logs? How are logs evaluated in a way that that's a security concern?

I didn't see this reply, sorry. I think I still answered it indirectly? 🤔

As a side note: I recommend reading this article about how an Emoji broke rust-analyzer, it is a good article which kind of explains the obscure things that can happen with user input.

[tlinhart]

I've created PRs for both discussed changes, please take a look.