mattwcole/gelf-extensions-logging

Increase precision of timestamp

tomap opened this issue · 7 comments

tomap commented

Currently, the timestamp is created as follow:

var totalMiliseconds = DateTimeOffset.UtcNow.ToUnixTimeMilliseconds();
var totalSeconds = totalMiliseconds / 1000d;
return Math.Round(totalSeconds, 2);

The precision is too low and should be increased otherwise messages will get the same timestamp, and in our case, kibana will display them in a random order
(our setup is .Net => Graylog => ElsticSearch => Kibana)

I tested with Math.Round(totalSeconds, 3); and it solved my issue (messages always get a different timestamp

Thank you

Great suggestion that will be a nice improvement!

tomap commented

Thanks
Also, I just opened the code with VSCode, which has a spell checker, and it said totalMilliseconds, not totalMiliseconds :)

Don't worry, that critical issue has already been taken care of!

tomap commented

Ah, I'm relieved

Could we increase it even more? On fast machine I have rapid bursts of logs from ASP .NET Core app that cause logs to have last 3 digits of timestamp to be the same. I am on linux and I think I have more than 1 ms resolution of time here.

Below are logs from Docker for my service. It looks I would need around 5- 6 digits to be exact.

2020-06-19T08:21:31.367563988Z info: Microsoft.AspNetCore.Hosting.Diagnostics[1]                                        
2020-06-19T08:21:31.367582508Z       Request starting HTTP/1.0 HEAD http:///                                            
2020-06-19T08:21:31.367586657Z info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]                                 
2020-06-19T08:21:31.367590815Z       Executing endpoint 'Xxxx.Controllers.VehicleDatabasesControl
2020-06-19T08:21:31.367594954Z info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]                 
2020-06-19T08:21:31.367615705Z       Route matched with {action = "Index", controller = "VehicleDatabases", page = ""}.                                                           

@MichalSznajder sure, I don't see any reason why we shouldn't increase the precision if we are able to. I can look at doing so over the weekend, or feel free to put up a PR if you like.

I had a look at this, and I'm not sure that the GELF protocol supports timestamps with more than 1ms of precision. You should be able to attach your own more precise timestamp as an additional filed.

https://docs.graylog.org/en/3.2/pages/gelf.html