LogEntry timestamps truncated to seconds

[vdm]

New GCE VM, just installed latest version Stackdriver Logging agent. This reproduces across several different VMs, agents, Debian and Centos.

Sub-second timestamps were included in fluentd <0.14, which google-fluentd appears to use. Why are timestamps still truncated in Stackdriver Logging?

[qingling128]

Hi @vdm, sub-second timestamps should be supported in the latest version Stackdriver Logging agent. Can you give some example of the issue you saw? Sample entries and resulting logs for example.

[ahprez]

I seem to have the same problem. My app runs on a GCE VM which has the latest google-fluentd 1.5.17 installed. Here is a log entry sample from our app, followed by the configuration:

2017-08-09 21:11:37,849 thread-1 INFO [MyApp] Hello World!

<source>
  type tail
  format multiline
  format_firstline /\d{4}-\d{1,2}-\d{1,2}/
  format1 /^(?<time>\d{4}-\d{1,2}-\d{1,2} \d{1,2}:\d{1,2}:\d{1,2},\d{3}) (?<thread>.*) (?<severity>[^\s]+) \[(?<serviceName>.*)\] (?<message>.*)/ 
  time_format %F %T,%L
  path /foo/bar/myservice.log
  pos_file /var/lib/google-fluentd/pos/myservice.pos
  read_from_head true
  tag myservice
</source>

In Stackdriver, the time for this log entry shows as 21:11:37.000. Any ideas why the milliseconds aren't appearing?

[sayap]

Same here. With google-fluentd 1.5.17-1, the timestamps are truncated to seconds.

[sayap]

Managed to get sub-second resolution after making this change to fluentd:

--- a/lib/fluent/time.rb
+++ b/lib/fluent/time.rb
@@ -73,7 +73,7 @@ module Fluent
     end
 
     def to_msgpack(io = nil)
-      @sec.to_msgpack(io)
+      to_f.to_msgpack(io)
     end
 
     def to_msgpack_ext

[qingling128]

Hi @sayap, which Fluentd version is this? You can check it with:

$ /opt/google-fluentd/embedded/bin/gem list | grep fluentd
fluentd (0.14.19)

Fluentd 0.12 does not have miliseconds support as I know. If it's the latest Fluentd version, you might want to submit a ticket (or a PR) in the Fluentd project.

[sayap]

@qingling128 It is already on 0.14, but still need the patch above to get nanosecond resolution timestamps into stackdriver:

$ /opt/google-fluentd/embedded/bin/gem list | grep fluentd
fluentd (0.14.19)

[igorpeshansky]

@sayap This is a bug in upstream fluentd code. We pull the upstream gem as-is, with no changes. Can you please open an issue or even send a PR, as @qingling128 requested, and reference it here? Once that's merged and released, we'll pick that up. Thanks.

[sayap]

Actually, fluentd already defines to_msgpack_ext which does the right thing, and doesn't suffer from floating point conversion issue (https://stackoverflow.com/a/18707602) like my patch above.

So, the patch above can be thrown away and replaced with something like this instead:

--- a/lib/fluent/plugin/out_google_cloud.rb
+++ b/lib/fluent/plugin/out_google_cloud.rb
@@ -1518,7 +1518,8 @@ module Fluent
     end
 
     def format(tag, time, record)
-      [tag, time, record].to_msgpack
+      packer = Fluent::MessagePackFactory.packer
+      packer.pack([tag, time, record]).to_s
     end
 
     # Given a tag, returns the corresponding valid tag if possible, or nil if

That works for me, but you may want to check with @mururu about the proper way to "activate" to_msgpack_ext.

[mururu]

For v0.12 style plugins + nanosecond resolution, Fluent::Engine.msgpack_factory.packer.write([tag, time, record]).to_s is better.
If this plugins also have to support 0.12.16 or earlier with same code, then you may need this kind of existence check for Fluent::Engine.msgpack_factory/Fluent::EventTime: mururu/fluent-plugin-elasticsearch@e671e36.

[psyonix-luis]

We're also experiencing the same issue on fluentd (0.14.19). I saw a PR was opened and approved, hope you guys can get that in soon, thanks!

[igorpeshansky]

#161 is merged.