IPv6 ASN lookup throws exception: #<NoMethodError: undefined method `to_hash' for ...

[jordansissel]

(Migrated from https://github.com/elastic/logstash/issues/3235; filed by @jannae)

---

I'm at a bit of a loss, so any help is appreciated. I'm getting a few errors that seem to have brought my ELK instance to it's knees. It stops dead on these, each time I attempt to restart or update the config in any way. Not sure what to make of it, as all my research has led me to previously corrected issues.

It seems related to this:

https://logstash.jira.com/browse/LOGSTASH-1394

Though this is indicated as having been corrected. :(

Also, if you need to review my configs they are here: https://github.com/jannae/logstash-configs

This may or may not be related to my recent upgrade to 1.5.0 rc4, it's tough to tell, except that this is a brand new problem for me, so, seems plausible.

{:timestamp=>"2015-05-12T22:11:44.302000-0400",
    :message=>"Exception in filterworker",
        "exception"=>#<NoMethodError: undefined method `to_hash' for "*AS18144 Energia Communications,Inc.":String>,
        "backtrace"=>["/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-geoip-0.1.9/lib/logstash/filters/geoip.rb:119:in `filter'",
        "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/filters/base.rb:162:in `multi_filter'",
        "org/jruby/RubyArray.java:1613:in `each'",
        "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/filters/base.rb:159:in `multi_filter'",
        "(eval):10100:in `cond_func_383'",
        "org/jruby/RubyArray.java:1613:in `each'",
        "(eval):10094:in `cond_func_383'",
        "(eval):3085:in `filter_func'",
        "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/pipeline.rb:219:in `filterworker'",
        "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/pipeline.rb:156:in `start_filters'"],
    :level=>:error}
{:timestamp=>"2015-05-12T22:11:44.349000-0400",
    :message=>"Exception in filterworker",
        "exception"=>#<NoMethodError: undefined method `to_hash' for "*AS18144 Energia Communications,Inc.":String>,
        "backtrace"=>["/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-geoip-0.1.9/lib/logstash/filters/geoip.rb:119:in `filter'",
        "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/filters/base.rb:162:in `multi_filter'",
        "org/jruby/RubyArray.java:1613:in `each'",
        "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/filters/base.rb:159:in `multi_filter'",
        "(eval):10100:in `cond_func_383'",
        "org/jruby/RubyArray.java:1613:in `each'",
        "(eval):10094:in `cond_func_383'",
        "(eval):3085:in `filter_func'",
        "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/pipeline.rb:219:in `filterworker'",
        "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/pipeline.rb:156:in `start_filters'"],
    :level=>:error}
{:timestamp=>"2015-05-12T22:11:44.427000-0400",
    :message=>"Exception in filterworker",
        "exception"=>#<NoMethodError: undefined method `to_hash' for "*AS18144 Energia Communications,Inc.":String>,
        "backtrace"=>["/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-geoip-0.1.9/lib/logstash/filters/geoip.rb:119:in `filter'",
        "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/filters/base.rb:162:in `multi_filter'",
        "org/jruby/RubyArray.java:1613:in `each'",
        "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/filters/base.rb:159:in `multi_filter'",
        "(eval):10100:in `cond_func_383'",
        "org/jruby/RubyArray.java:1613:in `each'",
        "(eval):10094:in `cond_func_383'",
        "(eval):3085:in `filter_func'",
        "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/pipeline.rb:219:in `filterworker'",
        "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/pipeline.rb:156:in `start_filters'"],
    :level=>:error}

(Migrated from https://github.com/elastic/logstash/issues/3235; filed by @jannae)

[jordansissel]

@jannae This definitely seems like a bug.

[colinsurprenant]

@jannae would it be possible to provide sample input that triggers this problem so we can reproduce? Also could you share your config? in particular I'd like to see the database => option.

@jordansissel the problem reported in LOGSTASH-1394 is similar but the missing to_hash method was on a <GeoIP::ASN:0x66dc722d> object and here it is on a String object. For some reason, the GeoIP call results in a String - either this due to an geoip gem upgrade and/or we do not correctly handle the database specified.

[jordansissel]

@colinsurprenant I agree with your assessment. :)

[joshskidmore]

I'm also having this issue, but only with the GeoIPASNum.dat database. When using just the GeoLiteCity.dat database, it works perfectly.

Hope this helps.

Exception:

Exception in filterworker {"exception"=>#<NoMethodError: undefined method `to_hash' for "*AS18144 Energia Communications,Inc.":String>, "backtrace"=>["/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-geoip-0.1.9/lib/logstash/
filters/geoip.rb:119:in `filter'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/filters/base.rb:162:in `multi_filter'", "org/jruby/RubyArray.java:1613:in `each'", "/opt/logstash/vendor/bundle/jr
uby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/filters/base.rb:159:in `multi_filter'", "(eval):323:in `cond_func_5'", "org/jruby/RubyArray.java:1613:in `each'", "(eval):317:in `cond_func_5'", "(eval):236:in `filter_func'", "/op
t/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/pipeline.rb:219:in `filterworker'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/pipeline.rb:156:in `start_filte
rs'"], :level=>:error}

Working config:

filter {
  if [type] == "nginx-access" {
    grok {
      match => { "message" => "%{IPORHOST:clientip} %{USER:ident} %{USER:auth} \[%{HTTPDATE:timestamp}\]  \"(?:%{WORD:verb} %{NOTSPACE:request}(?: HTTP/%{NUMBER:httpversion})?|-)\" %{NUMBER:response} (?:%{NUMBER:bytes}|-) \"(?:%{URI:referrer}|-)\" %{QS:agent} %{NUMBER:request_time} %{NUMBER:upstream_response_time}%{GREEDYDATA}" }
    }
    geoip {
        source => "clientip"
        target => "geoip"
        database => "/etc/geolite/GeoLiteCity.dat"
        add_field => [ "[geoip][coordinates]", "%{[geoip][longitude]}" ]
        add_field => [ "[geoip][coordinates]", "%{[geoip][latitude]}"  ]
    }
    mutate {
        convert => [ "[geoip][coordinates]", "float"]
    }
    date {
        match => [ "timestamp", "dd/MMM/yyyy:HH:mm:ss Z" ]
    }
  }
}

Config causing above exception (using GeoIPASNum.data database):

filter {
  if [type] == "nginx-access" {
    grok {
      match => { "message" => "%{IPORHOST:clientip} %{USER:ident} %{USER:auth} \[%{HTTPDATE:timestamp}\]  \"(?:%{WORD:verb} %{NOTSPACE:request}(?: HTTP/%{NUMBER:httpversion})?|-)\" %{NUMBER:response} (?:%{NUMBER:bytes}|-) \"(?:%{URI:referrer}|-)\" %{QS:agent} %{NUMBER:request_time} %{NUMBER:upstream_response_time}%{GREEDYDATA}" }
    }
    geoip {
        source => "clientip"
        target => "geoip"
        database => "/etc/geolite/GeoLiteCity.dat"
        add_field => [ "[geoip][coordinates]", "%{[geoip][longitude]}" ]
        add_field => [ "[geoip][coordinates]", "%{[geoip][latitude]}"  ]
    }
    mutate {
        convert => [ "[geoip][coordinates]", "float"]
    }
    geoip {
        source => "clientip"
        target => "geoip"
        database => "/etc/geolite/GeoIPASNum.dat"
    }
    date {
        match => [ "timestamp", "dd/MMM/yyyy:HH:mm:ss Z" ]
    }
  }
}

[colinsurprenant]

This is very weird. I cannot reproduce in 1.5.0.rc4, 1.5.0.snapshot1 and current master. I noticed that both @joshskidmore and @jannae config have a dual geoip, first with GeoLiteCity then GeoIPASNum. So my test does that:

bin/logstash -e 'input{stdin{}} filter{geoip{source => "message" target => "geoip"} geoip{source => "message" target => "geoip" database => "./vendor/bundle/jruby/1.9/gems/logstash-filter-geoip-0.1.9/vendor/GeoIPASNum-2014-02-12.dat"}} output{stdout{codec => rubydebug}}'
Logstash startup completed
202.7.112.10
{
       "message" => "202.7.112.10",
      "@version" => "1",
    "@timestamp" => "2015-05-14T15:28:45.785Z",
          "host" => "colin-mbp13r",
         "geoip" => {
                      "ip" => "202.7.112.10",
           "country_code2" => "JP",
           "country_code3" => "JPN",
            "country_name" => "Japan",
          "continent_code" => "AS",
             "region_name" => "45",
               "city_name" => "Hofu",
                "latitude" => 34.05000000000001,
               "longitude" => 131.56670000000003,
                "timezone" => "Asia/Tokyo",
        "real_region_name" => "Yamaguchi",
                "location" => [
            [0] 131.56670000000003,
            [1] 34.05000000000001
        ],
                  "number" => "AS18144",
                     "asn" => "Energia Communications,Inc."
    }
}

Here I use IP 202.7.112.10 but I actually tested all IP ranges from https://ipinfo.io/AS18144 since both problems involve "*AS18144 Energia Communications,Inc."

I am wondering if that could be caused by older/stale databases? I see both configs point to /etc/geolite/... and /opt/logstash/vendor/geoip/...

[joshskidmore]

I'm using the latest GeoIPASNum.dat (from two days ago), 3884250 bytes and md5sum of 1384810acaaa30b22eaf3db0f0455c5d.

[joshskidmore]

A probably stupid question - both my @jannae's configs use two GeoIP database (GeoCity and GeoIPASNum) - could that have anything to do with the issue?

UPDATE: Nevermind. I'm apparently not doing a great job at reading today.

[colinsurprenant]

@joshskidmore can you try using the included ASNum database included? database => "./vendor/bundle/jruby/1.9/gems/logstash-filter-geoip-0.1.9/vendor/GeoIPASNum-2014-02-12.dat

[colinsurprenant]

@joshskidmore also, can you retrieve a sample log which reproduce the problem on your end?

[colinsurprenant]

I just tried with the latest GeoIPASNum from http://dev.maxmind.com/geoip/legacy/geolite/ and still cannot reproduce O_o

[joshskidmore]

Sorry, it took a while to have the exception thrown.

The command I used: $ ./bin/logstash --verbose --debug -f /etc/logstash/conf.d/all.conf # all.conf

Because I was running this via CLI, and I was on a screen session with a short history buffer, all I have is the end. It appears that the previous Logstash insert had completed successfully, and the exception was thrown from what appears to be an IP from the same ASN:

   [... long stdout ...]

   "real_region_name" => "South Carolina",
                "location" => [
            [0] -79.7896,
            [1] 32.86959999999999
        ],
             "coordinates" => [
            [0] -79.7896,
            [1] 32.86959999999999
        ],
                  "number" => "AS16863",
                     "asn" => "Home Telephone Company, Inc."
    }
}
Exception in filterworker {"exception"=>#<NoMethodError: undefined method `to_hash' for "*AS18144 Energia Communications,Inc.":String>, "backtrace"=>["/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-geoip-0.1.9/lib/logstash/
filters/geoip.rb:119:in `filter'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/filters/base.rb:162:in `multi_filter'", "org/jruby/RubyArray.java:1613:in `each'", "/opt/logstash/vendor/bundle/jr
uby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/filters/base.rb:159:in `multi_filter'", "(eval):328:in `cond_func_5'", "org/jruby/RubyArray.java:1613:in `each'", "(eval):322:in `cond_func_5'", "(eval):240:in `filter_func'", "/op
t/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/pipeline.rb:219:in `filterworker'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0.rc4-java/lib/logstash/pipeline.rb:156:in `start_filte
rs'"], :level=>:error}

Also - I was able to use your inline/CLI command with both the vendor ASN database as well as the most recent from Maxmind without any issue.

[colinsurprenant]

@joshskidmore would you be able to isolate a/the log line which triggers the exception and share it?

[joshskidmore]

@colinsurprenant - I must be going crazy! I've went through all our logs and cannot find an asn/org match on "AS18144" or "Energia Communications." I'm going to do some further debugging to see if I can determine what's happening.

[colinsurprenant]

@joshskidmore the log line triggering the error will certainly not contain "AS18144" or "Energia Communications" since these strings are the result of the GeoIPASNum database lookup.

[joshskidmore]

I just wrote a quick utility to pull the IPs out of the log and do an ASN lookup against the Maxmind ASN database.

[colinsurprenant]

@joshskidmore another option from within logstash would be to add a custom Ruby filter to print the content of the event just before the geoip filter using GeoIPASNum. So reprocessing the logs will eventually crash but we'll see on stdout the last event content. Can you try that with:

ruby { 
  code => "puts(event.to_hash.inspect)"
}

[jannae]

Thank you guys so much for getting to work on this! I hadn't had a free moment to get back to it to search my logs, but this ruby output option seems like a good one, I will add and see what I find.

The offending line seems to have rotated out of my logs, as we're back to starting ok now. I will need to go back and load them soon though, and I can hopefully detect the line then and let you know.

[joshskidmore]

@colinsurprenant - Your pre-geoip logging is in and running. As soon as it dies, I'll get you a log line! I really appreciate the help; Ruby is definitely not my language.

[drahtGitter]

I have the exact same problem as @joshskidmore with pretty much the same configuration (first GeoIPCity, then Asnum) and also the most recent maxmind-databases. I used the pre-geoip-logging as well and got the exact same error when an event contains an IPV6 address. I'm desperately waiting for logstash-geoip to support ipv6, but the citylite-filter on its own at least doesn't kill logstash when it hits an ipv6-address.

[colinsurprenant]

@drahtGitter can you share a sample log which reproduces the error or can you share the output of your pre-geoip-logging ?

[drahtGitter]

{"message"=>"2a02:8071:aa1:c700:7984:22fc:c8e6:f6ff - - [01/May/2015:10:05:26 +0200] \"GET /foobar/ HTTP/1.1\" 301 591 \"-\" \"Mozilla/5.0 (Windows NT 6.3; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.135 Safari/537.36\"\r", "@version"=>"1", "@timestamp"=>"2015-05-01T08:05:26.000Z", "host"=>"sysop-VirtualBox", "path"=>"/home/sysop/Schreibtisch/data/apache.log", "clientip"=>"2a02:8071:aa1:c700:7984:22fc:c8e6:f6ff", "ident"=>"-", "auth"=>"-", "timestamp"=>"01/May/2015:10:05:26 +0200", "verb"=>"GET", "request"=>"/kontakt/", "httpversion"=>"1.1", "response"=>"301", "bytes"=>"591", "referrer"=>"\"-\"", "agent"=>"\"Mozilla/5.0 (Windows NT 6.3; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2311.135 Safari/537.36\""}

Exception in filterworker {"exception"=>#<NoMethodError: undefined method `to_hash' for "*AS18144 Energia Communications,Inc.":String>, "backtrace"=>["/home/sysop/Schreibtisch/data/logstash-1.5.0/vendor/bundle/jruby/1.9/gems/logstash-filter-geoip-0.1.9/lib/logstash/filters/geoip.rb:119:in `filter'", "/home/sysop/Schreibtisch/data/logstash-1.5.0/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0-java/lib/logstash/filters/base.rb:162:in `multi_filter'", "org/jruby/RubyArray.java:1613:in `each'", "/home/sysop/Schreibtisch/data/logstash-1.5.0/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0-java/lib/logstash/filters/base.rb:159:in `multi_filter'", "(eval):194:in `filter_func'", "/home/sysop/Schreibtisch/data/logstash-1.5.0/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0-java/lib/logstash/pipeline.rb:219:in `filterworker'", "/home/sysop/Schreibtisch/data/logstash-1.5.0/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.0-java/lib/logstash/pipeline.rb:156:in `start_filters'"], :level=>:error}

Config snippet:

geoip {
    source => "clientip"
    target => "geoip"
    database => "/usr/share/GeoIP/GeoLiteCity.dat"
  }

  ruby { 
    code => "puts(event.to_hash.inspect)"
  }

  geoip {
    source => "clientip"
    target => "geoip"
    database => "/usr/share/GeoIP/GeoIPASNum.dat"
   }

[joshskidmore]

@colinsurprenant I'm still here, but haven't had time to thoroughly test things. When I tested on Friday, I could not get consistent results.

On my initial attempt, the ruby debugging inspection code helped me realize a had a grokparser issue (I could now see it in the tags of the event hash output). I assumed that maybe this was causing other issues further downstream in the pipeline. I resolved the grok pattern issue, and started processing again.

On the next attempt (and subsequent attempts), Logstash runs error-free (no errors, no grokparse tags, etc) for a few minutes. It then stops processing messages altogether. The last item in the log was the debug info generated from "stdout { codec => rubydebug }" in the output - not the ruby inspect in the filter section.

Not really sure what's happening.

[colinsurprenant]

@drahtGitter \o/ bingo! ipv6. I can reproduce using:

bin/logstash -e 'input{stdin{}} filter{geoip{source => "message" target => "geoip"} geoip{source => "message" target => "geoip" database => "./vendor/bundle/jruby/1.9/gems/logstash-filter-geoip-0.1.9/vendor/GeoIPASNum-2014-02-12.dat"}} output{stdout{codec => rubydebug}}'
Logstash startup completed
2a02:8071:aa1:c700:7984:22fc:c8e6:f6ff
Exception in filterworker {"exception"=>#<NoMethodError: undefined method `to_hash' for "*AS9737 TOT Public Company Limited":String>, "backtrace"=>["/Users/colin/dev/src/elasticsearch/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-geoip-0.1.9/lib/logstash/filters/geoip.rb:119:in `filter'", "/Users/colin/dev/src/elasticsearch/logstash/lib/logstash/filters/base.rb:162:in `multi_filter'", "org/jruby/RubyArray.java:1613:in `each'", "/Users/colin/dev/src/elasticsearch/logstash/lib/logstash/filters/base.rb:159:in `multi_filter'", "(eval):67:in `filter_func'", "/Users/colin/dev/src/elasticsearch/logstash/lib/logstash/pipeline.rb:219:in `filterworker'", "/Users/colin/dev/src/elasticsearch/logstash/lib/logstash/pipeline.rb:156:in `start_filters'"], :level=>:error}

[colinsurprenant]

I just did a few tests and looked at the code and IPv6 is just not supported. The geoip gem does not correctly support IPv6 addresses per the iptonum method called from the asn method

Also the IPv6 version of the ASN DB would need to be used.

For a short term fix we can at least trap this and avoid crashing. I will submit a PR for this shortly. Otherwise I see an open issue about APv6 support in cjheath/geoip#17 - we'll see if we can submit a PR in the geoip project to fix this.

Also changing the issue subject to reflect this.

[colinsurprenant]

I just published version 0.1.10 of the logstash-filter-geoip plugin. You can update it using

bin/plugin update logstash-filter-geoip

The fix behaviour is to simply ignore such invalid lookups.

Please let me know if that help.

[joshskidmore]

Thank's @colinsurprenant! Wish I could have been more help with this one.

[colinsurprenant]

@joshskidmore :thumbsup: let me know if this works for you.

Also, worth noting I realized there was a PR #8 proposed to support IPv6. I will review shortly to make this happen too.

[drahtGitter]

Excellent - thank you very much @colinsurprenant

[colinsurprenant]

Before closing this I'd really like to know if it solved it for @joshskidmore and @jannae

[joshskidmore]

@colinsurprenant - it's been running (at high volume) for about two days now. Seems fixed!

[colinsurprenant]

I will go ahead and close this. Thanks @jannae @joshskidmore @drahtGitter