Elasticsearch-rails: Sporadic error: The bulk request must be terminated by a newline

[zainzafar]

Hi,

I'm importing 500 records in rails using the bulk method, however, on and off I get the following error:

Elasticsearch::Transport::Transport::Errors::BadRequest: [400] {"error":{"root_cause":[{"type":"illegal_argument_exception","reason":"The bulk request must be terminated by a newline [\n]"}],"type":"illegal_argument_exception","reason":"The bulk request must be terminated by a newline [\n]"},"status":400}

My environment:
Elasticsearch version: 6.5.4
Rails: 5.1.6

elasticsearch (6.1.0)
elasticsearch-api (6.1.0)
elasticsearch-model (6.0.0)
elasticsearch-rails (6.0.0)
elasticsearch-transport (6.1.0)

[karmi]

@zainzafar , that's interesting — can you post an example of how you're calling the Bulk API in your code?

[zainzafar]

@karmi here's the code snippet in ruby that's called for bulk indexing:

def self.bulk_index(indexables)
  self.__elasticsearch__.client.bulk({
    index: self.__elasticsearch__.index_name,
    type: self.__elasticsearch__.document_type,
    body: prepare_records(indexables),
    pipeline: :parse_ip_ua
  })
end

def self.prepare_records(indexables)
  indexables.map do |indexable|
    { index: { _id: indexable.id, data: indexable.as_indexed_json } }
  end
end

[zainzafar]

There's definitely something wrong with elasticsearch-rails client. Now getting the following error:

Elasticsearch::Transport::Transport::Errors::BadRequest ([400] {"error":{"root_cause":[{"type":"illegal_argument_exception","reason":"Malformed action/metadata line [75], expected START_OBJECT or END_OBJECT but found [VALUE_NUMBER]"}],"type":"illegal_argument_exception","reason":"Malformed action/metadata line [75], expected START_OBJECT or END_OBJECT but found [VALUE_NUMBER]"},"status":400})

[zainzafar]

Is there any way to log the bulk HTTP request's headers/body etc?

[karmi]

Yes, indeed: when you enable the DEBUG level for logging, both request and response bodies are logged. Please post the output when you have it.

There's a fairly extensive example here: https://github.com/elastic/elasticsearch-rails/blob/master/elasticsearch-model/examples/activerecord_associations.rb, where you can see how to setup the logger, and play with it so it resembles what you're doing in the code. I'm afraid I don't have any immediate idea about what's going wrong in your case, based on the Elasticsearch error responses.

[zainzafar]

Thanks for the pointing that out @karmi. I now have the output of an actual POST request to elastic.co server along with the error response (\n) missing. Since the payload contains some sensitive data, is there a way I could share that with you privately?

[nerfologist]

Hello, in our company we are experiencing the very same error when trying to import a bunch (~500) of Rails models; it really seems to be an unpredictable error, occurring about 50% of the times when we try to import ~ 60 records.

Edit: tried importing a different model with smaller records to its own index; it was able to import 19,170 records before erroring out the same way.

Edit #2: this error appears to be related to using ruby 2.6.0 which we recently upgraded to, using RVM. It works fine if we roll back our ruby to 2.5.3.

    # rake task
    import_projects_desc = <<~DESC
      Import projects (FORCE=true if you want to drop index)

      $ bin/rails elasticsearch:import:projects
      $ bin/rails elasticsearch:import:projects FORCE=true
    DESC
    desc import_projects_desc
    task projects: :environment do
      Project.includes(:platforms).import force: ENV.fetch('FORCE', false)
    end

Elasticsearch version:

✎  $ elasticsearch --version
Version: 6.5.4, Build: oss/tar/d2ef93d/2018-12-17T21:17:40.758843Z, JVM: 1.8.0_152

Gems:

# Gemfile
# Elasticsearch integration
gem 'elasticsearch-model', github: 'elastic/elasticsearch-rails', branch: '6.x'
gem 'elasticsearch-rails', github: 'elastic/elasticsearch-rails', branch: '6.x'
gem 'elasticsearch-dsl',
    github: 'elasticsearch/elasticsearch-ruby',
    branch: '6.x',
    require: 'elasticsearch/dsl'

Resolved to:

# Gemfile.lock
GIT
  remote: https://github.com/elastic/elasticsearch-rails.git
  revision: bb1fc82b56b4eca76dbe9394bd842630e6c0424a
  branch: 6.x
  specs:
    elasticsearch-model (6.0.0)
      activesupport (> 3)
      elasticsearch (> 1)
      hashie
    elasticsearch-rails (6.0.0)

GIT
  remote: https://github.com/elasticsearch/elasticsearch-ruby.git
  revision: e3d31cd48d4f3970256ffacb4f3148fe10299794
  branch: 6.x
  specs:
    elasticsearch (6.1.0)
      elasticsearch-api (= 6.1.0)
      elasticsearch-transport (= 6.1.0)
    elasticsearch-api (6.1.0)
      multi_json
    elasticsearch-dsl (0.1.5)
    elasticsearch-transport (6.1.0)
      faraday
      multi_json

Upon running the import task, the entities seem to be successfully serialized and sent to the Elasticsearch service, which responds this way:

...
[request ends]

2019-01-29 15:27:16 +0100: < {"error":{"root_cause":[{"type":"illegal_argument_exception","reason":"The bulk request must be terminated by a newline [\n]"}],"type":"illegal_argument_exception","reason":"The bulk request must be terminated by a newline [\n]"},"status":400}
2019-01-29 15:27:16 +0100: [400] {"error":{"root_cause":[{"type":"illegal_argument_exception","reason":"The bulk request must be terminated by a newline [\n]"}],"type":"illegal_argument_exception","reason":"The bulk request must be terminated by a newline [\n]"},"status":400}
rails aborted!
Elasticsearch::Transport::Transport::Errors::BadRequest: [400] {"error":{"root_cause":[{"type":"illegal_argument_exception","reason":"The bulk request must be terminated by a newline [\n]"}],"type":"illegal_argument_exception","reason":"The bulk request must be terminated by a newline [\n]"},"status":400}
/Users/nerfologist/.rvm/gems/ruby-2.6.0@zooppa-core/bundler/gems/elasticsearch-ruby-e3d31cd48d4f/elasticsearch-transport/lib/elasticsearch/transport/transport/base.rb:205:in `__raise_transport_error'
/Users/nerfologist/.rvm/gems/ruby-2.6.0@zooppa-core/bundler/gems/elasticsearch-ruby-e3d31cd48d4f/elasticsearch-transport/lib/elasticsearch/transport/transport/base.rb:323:in `perform_request'
/Users/nerfologist/.rvm/gems/ruby-2.6.0@zooppa-core/bundler/gems/elasticsearch-ruby-e3d31cd48d4f/elasticsearch-transport/lib/elasticsearch/transport/transport/http/faraday.rb:20:in `perform_request'
/Users/nerfologist/.rvm/gems/ruby-2.6.0@zooppa-core/bundler/gems/elasticsearch-ruby-e3d31cd48d4f/elasticsearch-transport/lib/elasticsearch/transport/client.rb:143:in `perform_request'
/Users/nerfologist/.rvm/gems/ruby-2.6.0@zooppa-core/bundler/gems/elasticsearch-ruby-e3d31cd48d4f/elasticsearch-api/lib/elasticsearch/api/actions/bulk.rb:85:in `bulk'
/Users/nerfologist/.rvm/gems/ruby-2.6.0@zooppa-core/bundler/gems/elasticsearch-rails-bb1fc82b56b4/elasticsearch-model/lib/elasticsearch/model/importing.rb:123:in `block in import'
/Users/nerfologist/.rvm/gems/ruby-2.6.0@zooppa-core/bundler/gems/elasticsearch-rails-bb1fc82b56b4/elasticsearch-model/lib/elasticsearch/model/adapters/active_record.rb:90:in `block in __find_in_batches'
/Users/nerfologist/.rvm/gems/ruby-2.6.0@zooppa-core/gems/activerecord-5.2.2/lib/active_record/relation/batches.rb:136:in `block in find_in_batches'
/Users/nerfologist/.rvm/gems/ruby-2.6.0@zooppa-core/gems/activerecord-5.2.2/lib/active_record/relation/batches.rb:238:in `block in in_batches'
...

[zainzafar]

@nerfologist I'll also add that we're on Ruby 2.6.0 as well. That might as well be the issue here.

[karmi]

@nerfologist, many thanks for the aditional information! I'm a bit mystified about the error, since both elasticsearch-ruby and elasticsearch-rails have quite a bit of unit and integration tests for bulk, which I haven't seen failing, but I see we don't run those against Ruby 2.6, that might indeed be the culprit. I'll try to run them locally and see what't going on.

[karmi]

@zainzafar , sorry for the silence — I don't think the output is that much useful, if you can straight out see that it's missing an \n. At the moment, my theory is that it's probably somehow related to Ruby 2.6, as you suggest as well.

[zainzafar]

@karmi the output clearly shows \n at the end of the payload. My bet is on it being Ruby 2.6.

[karmi]

It's very much Ruby 2.6, which seems to cut off a portion of the body. See the report in https://github.com/ruby/ruby/pull/2058#issuecomment-452193105, where Elasticsearch bulk payloads are specifically mentioned.

Here's a detailed information about the bug: https://mensfeld.pl/2019/01/exploring-a-critical-netprotocol-issue-in-ruby-2-6-0p0-and-how-it-can-lead-to-a-security-problem/

Can you try on Ruby 2.6.1, which should have patched the bug?

[nerfologist]

Hello, I just ran some manual tests using ruby 2.6.1 and the problem seems to be solved. I was able to import all models correctly. Thanks for your attention and help!

[karmi]

Many thanks for the confirmation, @nerfologist !

@zainzafar, can you check with Ruby 2.6.1 on your side and close the issue if it solves the problem?

[zainzafar]

Yup, ruby 2.6.1 seems to be working smoothly! Thanks for pointing it out @nerfologist and thanks for finding the bug report @karmi