The Wayback Machine - https://web.archive.org/web/20201029072748/https://github.com/hynek/structlog/issues/81
Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Timestamper should allow providing our own timestamp #81

Open
AndreLouisCaron opened this issue Sep 18, 2016 · 2 comments
Open

Timestamper should allow providing our own timestamp #81

AndreLouisCaron opened this issue Sep 18, 2016 · 2 comments

Comments

@AndreLouisCaron
Copy link

@AndreLouisCaron AndreLouisCaron commented Sep 18, 2016

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
Copy link
Owner

@hynek hynek commented Sep 19, 2016

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
Copy link
Author

@AndreLouisCaron AndreLouisCaron commented Sep 22, 2016

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?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
2 participants
You can’t perform that action at this time.