Logstash: Timestamp parsing fails with "cannot convert instance of class org.jruby.RubyObject to class java.lang.String"

Created on 25 Aug 2015 · 13Comments · Source: elastic/logstash

Hi, using the logstash package on debian wheezy with the following versions:
logstash 1.5.4-1
openjdk-7-jre-headless:amd64 7u79-2.5.6-1~deb7u1

I'm getting the following message:

{:timestamp=>"2015-08-25T14:25:17.945000+1000", :message=>"Failed parsing date from field", :field=>"timestamp", :value=>"2015-08-25T04:25:17.000Z", :exception=>"cannot convert instance of class org.jruby.RubyObject to class java.lang.String", :config_parsers=>"yyyy-MM-dd HH:mm:ss.SSS,yyyy-MM-dd HH:mm:ss,SSS,yyyy-MM-dd HH:mm:ss,yyyy/MM/dd HH:mm:ss,MMM  d HH:mm:ss,MMM dd HH:mm:ss,dd/MMM/yyyy:HH:mm:ss Z,yyyy-MM-dd HH:mm:ss.SSSZ,yyyy-MM-dd'T'HH:mm:ss.SSSZ,yyyy-MM-dd'T'HH:mm:ssZ,E MMM dd HH:mm:ss yyyy Z", :config_locale=>"default=en_AU", :level=>:warn}

At this point I'm not quite sure what's causing it.
I'm suspecting the following tidbit in the config but cannot be certain (namely the _target_ part):

  date {
    match => ["timestamp",
               "yyyy-MM-dd HH:mm:ss.SSS",
               "yyyy-MM-dd HH:mm:ss,SSS",
               "yyyy-MM-dd HH:mm:ss",
               "yyyy/MM/dd HH:mm:ss",
               "MMM  d HH:mm:ss",
               "MMM dd HH:mm:ss",
               "dd/MMM/yyyy:HH:mm:ss Z",
               "yyyy-MM-dd HH:mm:ss.SSSZ",
               "yyyy-MM-dd'T'HH:mm:ss.SSSZ",
               "yyyy-MM-dd'T'HH:mm:ssZ",
               "E MMM dd HH:mm:ss yyyy Z"
              ]
    target => "timestamp"
    timezone => 'Australia/Melbourne'
  }

Any ideas?

unconfirmed

Source

frconil

Most helpful comment

im using convert and its work
mutate
{
convert => [ "DATE", "string" ]
}

date {

match => ["DATE", "ISO8601"]

}

javadifateme on 9 Jan 2016

👍11 😕3

All 13 comments

@frconil thanks for reporting. I cannot reproduce using the following:

tmp/date.conf

input { stdin {codec => json_lines {}}}
filter {
    date {
        match => ["timestamp",
                   "yyyy-MM-dd HH:mm:ss.SSS",
                   "yyyy-MM-dd HH:mm:ss,SSS",
                   "yyyy-MM-dd HH:mm:ss",
                   "yyyy/MM/dd HH:mm:ss",
                   "MMM  d HH:mm:ss",
                   "MMM dd HH:mm:ss",
                   "dd/MMM/yyyy:HH:mm:ss Z",
                   "yyyy-MM-dd HH:mm:ss.SSSZ",
                   "yyyy-MM-dd'T'HH:mm:ss.SSSZ",
                   "yyyy-MM-dd'T'HH:mm:ssZ",
                   "E MMM dd HH:mm:ss yyyy Z"
                  ]
        target => "timestamp"
        timezone => 'Australia/Melbourne'
      }
  }
  output { stdout {codec => rubydebug {}}}

$ bin/logstash -f tmp/date.conf
Logstash startup completed
{"timestamp":"2015-08-25T04:25:17.000Z"}
{
     "timestamp" => "2015-08-25T04:25:17.000Z",
      "@version" => "1",
    "@timestamp" => "2015-08-25T15:41:44.711Z",
          "host" => "colin-mbp13r.local"
}

What input+codec are you using? Are you using any other filters? Could you maybe share your complete config and a sample log line which reproduces the problem?

colinsurprenant on 25 Aug 2015

Thanks @colinsurprenant !

Using your debugging steps I managed to pinpoint the issue. Turns out my date block was duplicated in the logstash config (one per filter block).
After removing the duplicate it's processing the timestamp correctly (AFAICT with test data).

Will try the newly crafted config on a dev instance and will let you know if there's additional issues down the pipeline.

frconil on 26 Aug 2015

Confirming that moving the timestamp transform to its own filter instead of including it in every filter fixed it.

Thanks for the help!

frconil on 26 Aug 2015

@frconil great!! I am not sure how your date block was duplicated? could you provide an example? I definitely think you triggered a bug with this and we can certainly either improve detection of this situation or fix the bug... in any case the triggered error/exception is very difficult to map to the date/filter mis-configuration and we can improve this.

I will reopen so we can still track this!

colinsurprenant on 26 Aug 2015

here's what i trimmed down the config to:

filter {
  date {
    match => ["timestamp",
               "yyyy-MM-dd HH:mm:ss.SSS",
               "yyyy-MM-dd HH:mm:ss,SSS",
               "yyyy-MM-dd HH:mm:ss",
               "yyyy/MM/dd HH:mm:ss",
               "MMM  d HH:mm:ss",
               "MMM dd HH:mm:ss",
               "dd/MMM/yyyy:HH:mm:ss Z",
               "yyyy-MM-dd HH:mm:ss.SSSZ",
               "yyyy-MM-dd'T'HH:mm:ss.SSSZ",
               "yyyy-MM-dd'T'HH:mm:ssZ",
               "E MMM dd HH:mm:ss yyyy Z"
              ]
    target => "timestamp"
    timezone => 'Australia/Melbourne'
  }
}
filter {
    date {
    match => ["timestamp",
               "yyyy-MM-dd HH:mm:ss.SSS",
               "yyyy-MM-dd HH:mm:ss,SSS",
               "yyyy-MM-dd HH:mm:ss",
               "yyyy/MM/dd HH:mm:ss",
               "MMM  d HH:mm:ss",
               "MMM dd HH:mm:ss",
               "dd/MMM/yyyy:HH:mm:ss Z",
               "yyyy-MM-dd HH:mm:ss.SSSZ",
               "yyyy-MM-dd'T'HH:mm:ss.SSSZ",
               "yyyy-MM-dd'T'HH:mm:ssZ",
               "E MMM dd HH:mm:ss yyyy Z"
              ]
    target => "timestamp"
    timezone => 'Australia/Melbourne'
  }
}
input { stdin {codec => json_lines {}}}
output { stdout {codec => rubydebug {}}}

Here's the results I get from it:

 /opt/logstash/bin/logstash -f /root/logstash.conf
Logstash startup completed
{"timestamp":"2015-08-25T04:25:17.000Z"}
Failed parsing date from field {:field=>"timestamp", :value=>"2015-08-25T04:25:17.000Z", :exception=>"cannot convert instance of class org.jruby.RubyObject to class java.lang.String", :config_parsers=>"yyyy-MM-dd HH:mm:ss.SSS,yyyy-MM-dd HH:mm:ss,SSS,yyyy-MM-dd HH:mm:ss,yyyy/MM/dd HH:mm:ss,MMM  d HH:mm:ss,MMM dd HH:mm:ss,dd/MMM/yyyy:HH:mm:ss Z,yyyy-MM-dd HH:mm:ss.SSSZ,yyyy-MM-dd'T'HH:mm:ss.SSSZ,yyyy-MM-dd'T'HH:mm:ssZ,E MMM dd HH:mm:ss yyyy Z", :config_locale=>"default=en_AU", :level=>:warn}
{
     "timestamp" => "2015-08-25T04:25:17.000Z",
      "@version" => "1",
    "@timestamp" => "2015-08-26T22:00:06.905Z",
          "host" => "0.0.0.0",
          "tags" => [
        [0] "_dateparsefailure"
    ]
}

frconil on 27 Aug 2015

I can reproduce it on 1.5.3 with the minimal config

input { stdin{} }
filter {
    date {
      match => ["@timestamp", ISO8601]
    }
}
output { stdout{} }

The date filter internally use JODA method parseMillis(String) so I suppose JRuby try to cast the value to String and fail as @timestamp in my case or previous target of the date filter in @frconil case are LogstashTimestamp object

@colinsurprenant as this is an error specific to the date filter, I suppose it can be moved there

wiibaa on 27 Aug 2015

@wiibaa boom! exactly! thanks. Yes, we can move this to the date filter plugin and better handle the expected field value type.

colinsurprenant on 27 Aug 2015

I am having the same issue with the following configuration. Funny though I don't have anything defined in the filter!

input {
    jdbc {
    jdbc_driver_library => "./mysql-connector-java-5.1.37/mysql-connector-java-5.1.37-bin.jar"
    jdbc_driver_class => "com.mysql.jdbc.Driver"
    jdbc_connection_string => "jdbc:mysql://myhost:3306/mydb"
    jdbc_user => "user"
    jdbc_password => "pa55w0rd"
    #schedule => "* * * * *"
    statement => "select id from employees"
    jdbc_paging_enabled => "true"
    jdbc_page_size => "200000"
  }
}
output {
    stdout { codec => json_lines }
    elasticsearch {
        protocol => http
        index => "department"
        document_type => "employee"
        document_id => "%{uuid}"
        host => "localhost"
    }
}

mhawila on 26 Oct 2015

@mhawila - I have the same problem, found out the issue in our case. Will show lines, someone else please file the bug, this is my second time using logstash and first time using JRuby

If you install jruby with rvm or something similar, then run bundle install, then bundle open sequel you can fix the issue by changing this line: https://github.com/jeremyevans/sequel/blob/c6678741ce34aac52cff966ff6a6288ccb8d5b75/lib/sequel/adapters/jdbc.rb#L216 from:

props.setProperty("password", opts[:password])

to:

props.setProperty("password", opts[:password].value)

this occurs b/c of this line https://github.com/elastic/logstash/blob/master/lib/logstash/util/password.rb#L17 which hides passwords in logs, and thus requires calling .value on them.

This issue is different than the one regarding timestamps mentioned above in the comments, but the error message is deceivingly the same

cannot convert instance of class org.jruby.RubyObject to class java.lang.String

This issue came first when googling, so hopefully someone who isn't here for their first rodeo can help re-assign this properly, this is really my first night

hope that info helps anyone who is stuck and those maintaining, the tl;dr is that if you provide ajdbc_password, you will hit this issue with the current Gemfile.lock dep tree frozen in this way(git diff):

+    logstash-input-jdbc (2.0.3)
+      logstash-codec-plain
+      logstash-core (>= 2.0.0.beta2, < 3.0.0)
+      rufus-scheduler
+      sequel
     logstash-input-kafka (2.0.2)
       jruby-kafka (>= 1.2.0, < 2.0.0)
       logstash-codec-json
@@ -576,6 +581,7 @@ GEM
     sawyer (0.6.0)
       addressable (~> 2.3.5)
       faraday (~> 0.8, < 0.10)
+    sequel (4.27.0)
     simple_oauth (0.3.1)
     simplecov (0.10.0)
       docile (~> 1.1.0)
@@ -681,6 +687,7 @@ DEPENDENCIES
   logstash-input-http
   logstash-input-imap
   logstash-input-irc
+  logstash-input-jdbc
   logstash-input-kafka
   logstash-input-log4j
   logstash-input-lumberjack

I think that's all the relevant information. ping me with any questions, don't mind helping

ps - logstash is awesome