Force timestamp does not work anymore with eliot 1.11.0

[lebouquetin]

Using eliot 1.10.0, I have in my code some features which define timestamp of log messages, code written like this:

expected = datetime.datetime(2005, 10, 2, 8, 30, 48, 70500)
logger.debug("Message", timestamp=expected.timestamp())

Timestamp is ok using eliot 1.10.0 but with 1.11.0 it is now ignored.

Any idea?

[itamarst]

Sorry you're having issues, and thanks for reporting the issue.

It seems like you're using the bridge between Python's built-in logging and Eliot? Since logger.debug() isn't an Eliot API.

[lebouquetin]

hm... you right, but...

Let's look at files changed between 1.10.0 and 1.11.0 :

In eliot/_action.py you have the following code added:

    ## Message logging
    def log(self, message_type, **fields):
        """Log individual message."""
        fields[TIMESTAMP_FIELD] = time.time()
        fields[TASK_UUID_FIELD] = self._identification[TASK_UUID_FIELD]
        fields[TASK_LEVEL_FIELD] = self._nextTaskLevel().as_list()
        fields[MESSAGE_TYPE_FIELD] = message_type
        self._logger.write(fields, fields.pop("__eliot_serializer__", None))

I did not analyse the full diff, but I assumed in 1.11.0 you now overwrite a TIMESTAMP_FIELD field given in the fields dictionnary. This is exactly what we do: add some log messages with user-defined timestamp... the new API overwrite it.

[lebouquetin]

What I understand from a fast read of the diff:

• in 1.10.0 eliot also allow to give TIMESTAMP_FIELD as a parameter through the fields dictionnary
• in 1.11.0 the TIMESTAMP_FIELD is always filled by eliot itself.

This may be a cornercase or a will of the new version; but this breaks the way we use eliot. Can we expect a fix or is it a will of the eliot team? (or maybe I'm wrong and I do not understand what is new in eliot 1.11.0?)

[itamarst]

The timestamp field is built-in to Eliot, so my expectation was that Eliot would always set it—there are no unit tests that timestamp is overrideable, for example, which is why this change wasn't caught.

What's your use case for overriding the timestamp that Eliot generates?

[lebouquetin]

@itamarst we use eliot in a really full-stack environment. This "full stack" environment includes hardware and embedded software. Those parts are clock-synchronized with our python part, and they timestamp their logs themselves.

We use eliot in order to agregate logs from all these sources; data can arrive with a delay - so the timestamp which is interesting is the one already set in the log messages we receive (and push into eliot), not the time we push the message in eliot).

[itamarst]

I see. So two options I can think of:

1. You rename timestamp in your code to generated_timestamp, and that has the benefit that you can see the delay between when message was generated and when Eliot logged it.
2. I allow timestamp to be overrideable again. My worry here is that this can lead to unexpected behavior for other Eliot users, but on the other hand no one ever complained about the old behavior. And there's question of how easy that is to implement.

Unrelatedly, what sort of application is this hardware+software for, if you're willing to share?

[lebouquetin]

@RoPP @grignards what do you think the best solution is?

We work on a project involving physical measures (temperature, hygrometry, etc) an autonomous way (some sensors are driven by a firmware and an onboard computer manage the experimentation, store the data and manage logs for the complete device)

[lebouquetin]

hello @itamarst

The best for us would be to allow timestamp to be overrideable again: no change on our side. We could also use a generated_timestamp as you suggested. Both solutions are ok for us.

Let me know what you decide about overrideable timestamp again; for now we'll stay on 1.10.0 until you decide, then we'll plan to upgrade according to what it implies for our source code (we are not in a hurry to upgrade).

[itamarst]

I think I'll stick with current behavior; returning to old behavior would add more code in critical performance path. Thanks for taking the time to report this, for your feedback, and for your flexibility.

And if by the way you ever need some Eliot-related consulting work, or something related to scientific computing, let me know.