qryn icon indicating copy to clipboard operation
qryn copied to clipboard

Message ordering for logs with milliseconds precisions

Open dvillaume opened this issue 2 years ago • 7 comments

Hello,

we're facing an issue with logs ordering when souce precision is limited to milliseconds precision.

The logs in db are stored with the same timestamp_ns (ie. 1660814394000000000) so they appear in random order in guis and requests.

Do you think you can plan the addition of second ordering based on insertion date when timestamp_ns is the same ?

Regards

dvillaume avatar Aug 25 '22 08:08 dvillaume

Hello @dvillaume qryn supports high precision timestamps, so this is most likely due to the sender usnig a low precision timestamp. What's sending logs?

lmangani avatar Aug 25 '22 08:08 lmangani

Hello,

this are freeswitch(precision milliseconds) logs exported via syslog (precision second).

We remap freeswitch timestamp as event the event timestamp (using vector.dev ).

dvillaume avatar Aug 25 '22 08:08 dvillaume

Could you please share a sample logql push message to confirm you're shipping full timestamps?

lmangani avatar Aug 25 '22 08:08 lmangani

Well, we don't plan adding extra timestamps to the log field for now. Precision is on the sender. I can suggest adding nanosecond part of the log timestamp from the "now" time. like timestamp_of_log_sec * 1e9 * nanosecond_part_from_now_time. It can give you the right ordering. But of course it will be a custom lua plugin for vector.dev.

akvlad avatar Aug 25 '22 09:08 akvlad

firstly i apologize the precision of my logs are microseconds and not milliseconds.

I could add the nanosecond par from now, but would still make unordered messages when logs from same microseconds would be send at differnent milliseconds.

For example if my logs have a microseconds 1661418725208068, if i send on them at nanosec : 1661418725208068999 and the second one at 1661418725208069000 , the two logs would be unordered.

I may fallback on vector.dev now() timestamp, but may have unorder messages when logs are shipped from servers to centralized syslog server.

dvillaume avatar Aug 25 '22 09:08 dvillaume

@dvillaume well, that's strange because microsecond precision should give you pretty good ordering. Please take a look at this example https://vector.dev/docs/reference/configuration/transforms/lua/#examples-count-the-number-of-logs They make a counter and update it each new log line. You can make the same counter and add % 1000 of it (in case of microsecond precision) to the non-precise nanoseconds part. It should give you no overlapping unless you have more than 1000 log lines per millisecond.

akvlad avatar Aug 25 '22 10:08 akvlad

I may give it a try, adding a counter reset when microsenconds differs from previous, to avoid overlap when the counter reaches yyy9xx and goes to the upper thousand ie yyy+10xx.

I hope we'll never reach the 1000 logs limit. Thanks for you time and advices.

dvillaume avatar Aug 25 '22 12:08 dvillaume

I'm walking through old issues. @dvillaume is this issue still relevant for now?

akvlad avatar Oct 26 '22 12:10 akvlad

We bypassed it, thanks.

dvillaume avatar Oct 26 '22 12:10 dvillaume