Handle EventTime msgpack extension to handle nanosecond precision time and add its parameter

[cosmo0920]

Hi, I've tried to handle EventTime msgpack extension in this codec plugin.
How about start to handle EventTime extension?

Regards,

[cosmo0920]

With this nanosecond_precision parameter, logstash starts to handle subsecond like this:

fluent-cat with EventTime extention

$ echo '{"current_version":"v0.14", "versions":{"unstable":0.14, "stable":0.12}}' | bundle exec fluent-cat my.logs

logstash with this codec

logstash config w/ EventTime extension

input {
  tcp {
    codec => fluent {
      nanosecond_precision => true
    }
    port => 24224
  }
}
output {
  stdout { codec => json }
}

Output result

{"current_version":"v0.14","versions":{"stable":0.12,"unstable":0.14},"@version":"1","@metdata":{"ip_address":"127.0.0.1"},"@timestamp":"2018-01-04T09:25:45.489Z","port":56755,"tags":["my.logs"],"host":"localhost"}

---

Otherwise, logstash cannot handle subseconds:

fluent-cat with EventTime ext

$ echo '{"current_version":"v0.14", "versions":{"unstable":0.14, "stable":0.12}}' | bundle exec fluent-cat my.logs

logstash with this codec

logstash config w/o EventTime extension

input {
  tcp {
    codec => fluent
    port => 24224
  }
}
output {
  stdout { codec => json }
}

Output result

Nothing output.

[cosmo0920]

How about these changes?
These changes are also needed to handle EventTime which is included in new Fluentd protocol.
Thanks.

[dsolsona]

I had to change this to require_relative "event_time" to make it work on a new Logstash 6.2.2 setup otherwise you get {:exception=>#<LoadError: no such file to load -- logstash/codecs/fluent/event_time>

[cosmo0920]

Umm..., in my environment, require_relative "event_time" does not work. :'( require_relative "fluent/event_time" and require "logstash/codecs/fluent/event_time" work. 😖

[cosmo0920]

My plugin setup procedure is:

$ gem build logstash-codec-fluent.gemspec
$ logstash-plugin install logstash-codec-fluent-*.gem

[dsolsona]

Interesting. I'll do another test tomorrow and I'll let you know.

[dsolsona]

Hi @cosmo0920

I've tested your patch in a brand new Logstash 6.2.2 setup with fluentd-bit v0.12.14 and it works 👍

This is the output from using the tail input.

{
           "log" => "Tue Feb 27 05:41:46 UTC 2018 this is a test log entry",
    "@timestamp" => 2018-02-27T05:44:19.049Z,
          "tags" => [
        [0] "tail.0"
    ],
      "@version" => "1",
          "port" => 54206,
          "host" => "localhost"
}

Before this patch I wasn't getting anything in logstash and now I do.

[cosmo0920]

fluent-bit has fallback protocol mechanism.
time_as_integer options may be useful for the latest vanilla fluent codec:
https://github.com/fluent/fluent-bit-docs/blob/93cfe27006918044a0ff5e69eeeba4eafde651ab/output/forward.md#configuration-parameters-config_tcp

nanosecond_precision parameter name is referenced from fluent-logger-ruby's EventTime handling parameter:
https://github.com/fluent/fluent-logger-ruby#use-nanosecond-precision-time

[cosmo0920]

Any news?

[jsvd]

I just tested this locally with logstash 7.3.0:

bin/logstash -e "input { tcp { port => 44444 codec => fluent {nanosecond_precision => true } } } output { stdout { codec => rubydebug } }"

and fluent-logger (0.8.2):

> log = Fluent::Logger::FluentLogger.new(nil, :host => 'localhost', :port => 44444, :nanosecond_precision => true)
> log.post_with_time("myapp.access", {"agent" => "foo"}, Time.now)

And confirmed sending data with nanosecond_precision enabled on both sides no longer fails.

[cosmo0920]

Oh, thank you.

[jsvd]

@cosmo0920 sorry for the long delay, and thank you for the work done here.

[edit] very long delay.

[dcrn]

When will this be released? Currently hitting the issue resolved by this.

[ckoenig]

We are using the latest version of this plugin and are running into a problem, which in our opinion is caused by this line here. As far as I can see, calling Time.at with just two parameters, expects the second parameter to specify microseconds and not nanoseconds, which in our case changed the timestamps and suddenly added roughly 10 minutes.

Shouldn't this read Time.at(fluent_time.sec, fluent_time.nsec / 1000.0) instead?