Timestamper should allow providing our own timestamp

[AndreLouisCaron]

TL; DR: it would be convenient in some rare cases to allow providing our own timestamp. Right now, I need to reimplement structlog.processors.TimeStamper to do achieve this.

I'm writing a toy microservices PaaS (purely for educative purposes) and I'm currently working on request tracing for correlation of events across multiple services. The idea is that each service logs the request URL path, HTTP response status, processing time and request ID for each HTTP request so I an understand where errors are coming from (nothing new here).

Now that I've got something working, I noticed that events show up in a rather confusing order: since I log at request completion time to get the response status code, the timestamp of the request causes an order which looks time ordered across requests, but the order is reversed for sub-requests, which complete before the enclosing/source request (the one at the edge of the network).

It's trivial for me to record the arrival time of the request, so I'd like to use that and inject it in the event data I pass to logger.info('http.access', path=..., status=..., processing_time=..., timestamp=...).

From the looks of it, adding support for this is mostly replacing a few event_dict[key] = ... statements to event_dict.setdefault(key, ...), plus some docs to explain that the caller is responsible for formatting the timestamps themselves when they use this (OK for me, I always log iso anyways).

Would you be open to such a change? I'm willing to put in a PR if you're OK with this proposal :-)

[hynek]

That would slow it down for everyone. But you can work around pretty easily yourself without reimplementing anything (untested but should work):

class MaybeTimestamper(object):
    def __init__(self):
        self. stamper = structlog.processors.TimeStamper()
    def __call__(self, l, m, ev:):
        if "timestamp" not in ev:
            return self.stamper(l, m, ev)
        return ev

Am I missing something?

[AndreLouisCaron]

That would slow it down for everyone.

I know that calling .setdefault() for cases where the key is already in the dict usually has noticeable overhead, but that's mostly because you're computing something you don't need. How much slower is calling .setdefault() instead of .__setitem__() in cases where the key is not already present in the dictionary?

[hynek]

sorry for leaving this open for so long. the next version of structlog will come with MaybeTimeStamper.

[AndreLouisCaron]

Wow, thanks Hynek!