Error: undefined method `[]' for nil:NilClass in logstash

hongyuan1306 · June 29, 2016, 5:28am

With logstash 2.3.3 I encounter the following error with elasticssearch input plugin:

Error: undefined method[]' for nil:NilClass`

Following is my logstash config file:

input {
  elasticsearch {
    hosts => 'vhost02.homemaster.cn:9200'
    index => 'logstash-2016.06.*'
    query => '{"fields": ["clientIP"], "query": { "match_all": {} } }'
  }
}

output {
  stdout {
    codec => json
  }
}

The line that causes the error is:

query => '{"fields": ["clientIP"], "query": { "match_all": {} } }'

If it is changed to:

query => '{ "query": { "match_all": {} } }'

the error goes away.

It seems that logstash is treating the [] in the query string with some special meaning, probably as field names, while I would expect every in the string to be passed to elastics.

With --debug option the stacktrace is attached below:

  Error: undefined method `[]' for nil:NilClass
  Exception: NoMethodError
  Stack: /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-event-2.3.3-java/lib/logstash/event.rb:73:in `initialize'
/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-input-elasticsearch-2.0.5/lib/logstash/inputs/elasticsearch.rb:171:in `push_hit'
/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-input-elasticsearch-2.0.5/lib/logstash/inputs/elasticsearch.rb:166:in `process_next_scroll'
org/jruby/RubyArray.java:1613:in `each'
/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-input-elasticsearch-2.0.5/lib/logstash/inputs/elasticsearch.rb:166:in `process_next_scroll'
/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-input-elasticsearch-2.0.5/lib/logstash/inputs/elasticsearch.rb:149:in `run'
/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.3-java/lib/logstash/pipeline.rb:342:in `inputworker'
/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.3-java/lib/logstash/pipeline.rb:336:in `start_input' {:level=>:error, :file=>"logstash/pipeline.rb", :line=>"353", :method=>"inputworker"}

Is this a bug of logstash of there are some other way to pass the query to elasticsearch?

magnusbaeck · June 29, 2016, 5:43am

This looks like a Logstash bug, probably in the elasticsearch input. It should be initializing an event with a nil hash. I don't understand how that can happen though, unless the ES response is malformed. Can you use Wireshark or similar to sniff the request and response packets?

hongyuan1306 · June 29, 2016, 6:10am

Result with wireshark:

GET /logstash-2016.06.%2A/_search?scroll=1m&search_type=scan&size=1000 HTTP/1.1
User-Agent: Faraday v0.9.2
Accept: */*
Connection: close
Host: vhost02.homemaster.cn:9200
Content-Length: 55
Content-Type: application/x-www-form-urlencoded

{"fields": ["clientIP"], "query": { "match_all": {} } }HTTP/1.1 200 OK
Content-Type: application/json; charset=UTF-8
Content-Length: 371

{"_scroll_id":"c2Nhbjs1OzEzOTEwNDo2Y2dTa3p6ZlFqLTB6dTB6eXozenh3OzEzOTEwNTo2Y2dTa3p6ZlFqLTB6dTB6eXozenh3OzE0ODc0MDpvSENqVUROOFNMLVo2ZlU1Ukc4cmZBOzE0ODc0MTpvSENqVUROOFNMLVo2ZlU1Ukc4cmZBOzEzOTEwNjo2Y2dTa3p6ZlFqLTB6dTB6eXozenh3OzE7dG90YWxfaGl0czoxMTc7","took":1,"timed_out":false,"_shards":{"total":5,"successful":5,"failed":0},"hits":{"total":117,"max_score":0.0,"hits":[]}}



GET /_search/scroll?scroll=1m HTTP/1.1
User-Agent: Faraday v0.9.2
Accept: */*
Connection: close
Host: vhost02.homemaster.cn:9200
Content-Length: 232
Content-Type: application/x-www-form-urlencoded

c2Nhbjs1OzEzOTEwNDo2Y2dTa3p6ZlFqLTB6dTB6eXozenh3OzEzOTEwNTo2Y2dTa3p6ZlFqLTB6dTB6eXozenh3OzE0ODc0MDpvSENqVUROOFNMLVo2ZlU1Ukc4cmZBOzE0ODc0MTpvSENqVUROOFNMLVo2ZlU1Ukc4cmZBOzEzOTEwNjo2Y2dTa3p6ZlFqLTB6dTB6eXozenh3OzE7dG90YWxfaGl0czoxMTc7HTTP/1.1 200 OK
Content-Type: application/json; charset=UTF-8
Content-Length: 15281

{"_scroll_id":"c2NhbjswOzE7dG90YWxfaGl0czoxMTc7","took":2,"timed_out":false,"_shards":{"total":5,"successful":5,"failed":0},"hits":{"total":117,"max_score":0.0,"hits":[{"_index":"logstash-2016.06.29","_type":"log","_id":"AVWagR845YI_xmZDXo6D","_score":0.0,"fields":{"clientIP":["123.150.183.44"]}},{"_index":"logstash-2016.06.29","_type":"log","_id":"AVWanWiF5YI_xmZDXpaY","_score":0.0,"fields":{"clientIP":["52.3.127.144"]}}
...

The query is correctly sent to elastic and the response is also sent back. It's the way logstash process the response from elastics that causes the problem.

Can logstash not deal with "fields":{"clientIP":["52.3.127.144"]}?

magnusbaeck · June 29, 2016, 6:31am

The problem is that the second response doesn't include the _source field that's asked for here:

github.com

logstash-plugins/logstash-input-elasticsearch/blob/v2.0.5/lib/logstash/inputs/elasticsearch.rb#L171




private


def process_next_scroll(output_queue, scroll_id)
  r = scroll_request(scroll_id)
  r['hits']['hits'].each { |hit| push_hit(hit, output_queue) }
  {'has_hits' => r['hits']['hits'].any?, '_scroll_id' => r['_scroll_id']}
end


def push_hit(hit, output_queue)
  event = LogStash::Event.new(hit['_source'])
  decorate(event)


  if @docinfo
    # do not assume event[@docinfo_target] to be in-place updatable. first get it, update it, then at the end set it in the event.
    docinfo_target = event[@docinfo_target] || {}


    unless docinfo_target.is_a?(Hash)
      @logger.error("Elasticsearch Input: Incompatible Event, incompatible type for the docinfo_target=#{@docinfo_target} field in the `_source` document, expected a hash got:", :docinfo_target_type => docinfo_target.class, :event => event)


      # TODO: (colin) I am not sure raising is a good strategy here?

Did you disable source document storage in your index mappings? That could explain why there's no _source in the results, only fields.

hongyuan1306 · June 29, 2016, 7:38am

Now I understand that logstash depends on the'_source' field for proper operation. So my job succeeds now after changing the "fields" filter to "_source":

query => '{"_source": ["clientIP"], "query": { "match_all": {} } }'

Thanks for your prompt help.

magnusbaeck · July 1, 2016, 7:54pm

I've filed a GitHub issue for this bug: