uninitialized constant Fluent::EventTime

[eyablonowitz]

Starting with commit d3d1992d14cd8bc3576d8f7f0ea73332de63d963, I see errors like the below when using a fluentd configuration that includes a time_format parameter and the log line never makes it to the target (Graylog). Reverting to 1377c3e4f771e2066b27c86beafa81ed71b59141 resolved this issue for me.

Versions:

# dpkg --list | grep td-agent
ii  td-agent                           2.3.2-0                           amd64        Treasure Agent: A data collector for Treasure Data

# td-agent --version
td-agent 0.12.26

# lsb_release -a
No LSB modules are available.
Distributor ID: Debian
Description:    Debian GNU/Linux 7.9 (wheezy)
Release:    7.9
Codename:   wheezy

2016-09-22 02:43:28 +0000 [warn]: emit transaction failed: error_class=NameError error="uninitialized constant Fluent::EventTime" tag="graylog.foo"
  2016-09-22 02:43:28 +0000 [warn]: /etc/td-agent/plugin/out_gelf.rb:48:in `format'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/output.rb:282:in `block in format_stream'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/event.rb:130:in `call'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/event.rb:130:in `block in each'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/event.rb:129:in `each'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/event.rb:129:in `each'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/output.rb:281:in `format_stream'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/output.rb:267:in `emit'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/output.rb:42:in `next'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/plugin/out_copy.rb:78:in `emit'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/event_router.rb:90:in `emit_stream'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/plugin/in_tail.rb:269:in `receive_lines'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/plugin/in_tail.rb:373:in `call'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/plugin/in_tail.rb:373:in `wrap_receive_lines'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/plugin/in_tail.rb:568:in `call'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/plugin/in_tail.rb:568:in `on_notify'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/plugin/in_tail.rb:399:in `on_notify'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/plugin/in_tail.rb:500:in `call'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/plugin/in_tail.rb:500:in `on_change'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.4.4/lib/cool.io/loop.rb:88:in `run_once'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.4.4/lib/cool.io/loop.rb:88:in `run'
  2016-09-22 02:43:28 +0000 [warn]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.26/lib/fluent/plugin/in_tail.rb:253:in `run'

Here is my source configuration:

<source>
    type tail
    format /^(?<client_ip>[^ ]*) - (?<user>[^ ]*) \[(?<time>[^\]]*)\]\s+"(?<method>\S+)(?: +(?<path>[^\"]*) +\S*)? (?<status>[^ ]*) (?<size>[^ ]*) "(?<referer>[^\"]*)" "(?<user-agent>[^\"]*)" (?<hostname>[^ "]*) (?<request-time>[^ "]*) (?<upstream-time>[^ "]*)/
    time_format %d/%b/%Y:%T %z
    path /var/log/nginx/*.log
    pos_file /var/log/td-agent/nginx.pos
    tag graylog.foo
</source>

And my match:

<match graylog.**>
        type copy
            <store>
                        type gelf
                        host graylog.jana.dev
                        port 12201
                        flush_interval 5s
            </store>
</match>

And a log line:

10.11.12.13 - - [22/Sep/2016:02:27:35 +0000]  "POST /foo/foo HTTP/1.1" 200 14 "-" "Dalvik/2.1.0 (Linux; U; Android 6.0.1; SM-J700M Build/MMB29K)" foo 0.014 0.014 .

[eyablonowitz]

Looking over #20 from @gcs-github , I suspect the changes work fine in the fluentd >= .14 but are not backwards compatible for those of us running the current stable td-agent.

[gcs-github]

My bad, looks like I needed to test more thoroughly. I'll come up with a fix.

[gcs-github]

👆 PR open to fix this.

[qburst-praven]

@gcs-github , we were running into the same issue as mentioned above. I manually tested with the fix from the above PR, and confirmed that seems to fix the issue for us.

[gcs-github]

Thanks for the report @PravenJohn !

[emsearcy]

sorry for the delay. thanks all!