Elasticsearch::Transport::Transport::Errors::GatewayTimeout: [504]

[JoshTGreenwood]

I have been running into this error while trying to run a reindex on one of my models:

Elasticsearch::Transport::Transport::Errors::GatewayTimeout: [504]
/app/vendor/bundle/ruby/2.1.0/gems/elasticsearch-transport-1.0.4/lib/elasticsearch/transport/transport/base.rb:132:in `__raise_transport_error'
/app/vendor/bundle/ruby/2.1.0/gems/elasticsearch-transport-1.0.4/lib/elasticsearch/transport/transport/base.rb:224:in `perform_request'
/app/vendor/bundle/ruby/2.1.0/gems/elasticsearch-transport-1.0.4/lib/elasticsearch/transport/transport/http/faraday.rb:20:in `perform_request'
/app/vendor/bundle/ruby/2.1.0/gems/elasticsearch-transport-1.0.4/lib/elasticsearch/transport/client.rb:102:in `perform_request'
/app/vendor/bundle/ruby/2.1.0/gems/elasticsearch-api-1.0.4/lib/elasticsearch/api/actions/bulk.rb:81:in `bulk'
/app/vendor/bundle/ruby/2.1.0/gems/searchkick-0.8.2/lib/searchkick/index.rb:44:in `block in import'
/app/vendor/bundle/ruby/2.1.0/gems/searchkick-0.8.2/lib/searchkick/index.rb:43:in `each'
/app/vendor/bundle/ruby/2.1.0/gems/searchkick-0.8.2/lib/searchkick/index.rb:43:in `import'
/app/vendor/bundle/ruby/2.1.0/gems/searchkick-0.8.2/lib/searchkick/logging.rb:46:in `block in import_with_instrumentation'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.13/lib/active_support/notifications.rb:123:in `block in instrument'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.13/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
/app/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.13/lib/active_support/notifications.rb:123:in `instrument'
/app/vendor/bundle/ruby/2.1.0/gems/searchkick-0.8.2/lib/searchkick/logging.rb:45:in `import_with_instrumentation'
/app/vendor/bundle/ruby/2.1.0/gems/searchkick-0.8.2/lib/searchkick/reindex.rb:65:in `block in searchkick_import'
/app/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.13/lib/active_record/relation/batches.rb:72:in `find_in_batches'
/app/vendor/bundle/ruby/2.1.0/gems/searchkick-0.8.2/lib/searchkick/reindex.rb:64:in `searchkick_import'
/app/vendor/bundle/ruby/2.1.0/gems/searchkick-0.8.2/lib/searchkick/reindex.rb:20:in `reindex'
/app/vendor/bundle/ruby/2.1.0/gems/searchkick-0.8.2/lib/searchkick/tasks.rb:10:in `block (2 levels) in <top (required)>'

Here is the relevant model code:

# this is a simple has_many through relationship
scope :search_import, -> { includes(categories: [:categorizations]) } 

 def search_data 
    {
      id: id,
      title: title,
      published_at: published_at,
      body: body,
      site_id: site_id,
      category_ids: categories.map(&:id),
      user_id: user_id,
      sticky_until: sticky_until
    }
  end

Reindexing works locally but times out on Heroku(running ElasticSearch 1.3). I have other similar indexes that work fine both locally and on Heroku.

Any idea what's going on?

[ankane]

Not sure why it would be timing out, but lowering the batch size may fix it: searchkick batch_size: 100.

[diasks2]

I'm also running into a similar issue. Reindexing works fine locally and it works fine for all tables except one on Heroku. I tried reducing the batch size to 100 (and also to 10). I'll keep doing some more testing tomorrow. I am using seed_fu to seed the data and then I am trying to reindex once the seed data is loaded. I do not know if that is contributing to the issue. The field that is indexed on the table that is having trouble is a 'text' datatype that sometimes has long strings - that might also be a potential reason. I'll keep digging and let you know if I find anything.

Faraday::TimeoutError: Operation timed out after 5000 milliseconds with 0 bytes received
    from /app/vendor/bundle/ruby/2.1.0/gems/patron-0.4.18/lib/patron/session.rb:223:in `handle_request'
    from /app/vendor/bundle/ruby/2.1.0/gems/patron-0.4.18/lib/patron/session.rb:223:in `request'
    from /app/vendor/bundle/ruby/2.1.0/gems/faraday-0.9.0/lib/faraday/adapter/patron.rb:33:in `call'
    from /app/vendor/bundle/ruby/2.1.0/gems/faraday-0.9.0/lib/faraday/rack_builder.rb:139:in `build_response'
    from /app/vendor/bundle/ruby/2.1.0/gems/faraday-0.9.0/lib/faraday/connection.rb:377:in `run_request'
    from /app/vendor/bundle/ruby/2.1.0/gems/elasticsearch-transport-1.0.5/lib/elasticsearch/transport/transport/http/faraday.rb:21:in `block in perform_request'
    from /app/vendor/bundle/ruby/2.1.0/gems/elasticsearch-transport-1.0.5/lib/elasticsearch/transport/transport/base.rb:187:in `call'
    from /app/vendor/bundle/ruby/2.1.0/gems/elasticsearch-transport-1.0.5/lib/elasticsearch/transport/transport/base.rb:187:in `perform_request'
    from /app/vendor/bundle/ruby/2.1.0/gems/elasticsearch-transport-1.0.5/lib/elasticsearch/transport/transport/http/faraday.rb:20:in `perform_request'
    from /app/vendor/bundle/ruby/2.1.0/gems/elasticsearch-transport-1.0.5/lib/elasticsearch/transport/client.rb:104:in `perform_request'
    from /app/vendor/bundle/ruby/2.1.0/gems/elasticsearch-api-1.0.5/lib/elasticsearch/api/actions/bulk.rb:81:in `bulk'
    from /app/vendor/bundle/ruby/2.1.0/gems/searchkick-0.8.2/lib/searchkick/index.rb:44:in `block in import'
    from /app/vendor/bundle/ruby/2.1.0/gems/searchkick-0.8.2/lib/searchkick/index.rb:43:in `each'
    from /app/vendor/bundle/ruby/2.1.0/gems/searchkick-0.8.2/lib/searchkick/index.rb:43:in `import'
    from /app/vendor/bundle/ruby/2.1.0/gems/searchkick-0.8.2/lib/searchkick/logging.rb:46:in `block in import_with_instrumentation'
    from /app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.1.6/lib/active_support/notifications.rb:159:in `block in instrument'
    from /app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.1.6/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
    from /app/vendor/bundle/ruby/2.1.0/gems/activesupport-4.1.6/lib/active_support/notifications.rb:159:in `instrument'
    from /app/vendor/bundle/ruby/2.1.0/gems/searchkick-0.8.2/lib/searchkick/logging.rb:45:in `import_with_instrumentation'
    from /app/vendor/bundle/ruby/2.1.0/gems/searchkick-0.8.2/lib/searchkick/reindex.rb:65:in `block in searchkick_import'
    from /app/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.6/lib/active_record/relation/batches.rb:125:in `find_in_batches'
    from /app/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.6/lib/active_record/querying.rb:9:in `find_in_batches'
    from /app/vendor/bundle/ruby/2.1.0/gems/searchkick-0.8.2/lib/searchkick/reindex.rb:64:in `searchkick_import'
    from /app/vendor/bundle/ruby/2.1.0/gems/searchkick-0.8.2/lib/searchkick/reindex.rb:20:in `reindex'
    from (irb):3
    from /app/vendor/bundle/ruby/2.1.0/gems/railties-4.1.6/lib/rails/commands/console.rb:90:in `start'
    from /app/vendor/bundle/ruby/2.1.0/gems/railties-4.1.6/lib/rails/commands/console.rb:9:in `start'
    from /app/vendor/bundle/ruby/2.1.0/gems/railties-4.1.6/lib/rails/commands/commands_tasks.rb:69:in `console'
    from /app/vendor/bundle/ruby/2.1.0/gems/railties-4.1.6/lib/rails/commands/commands_tasks.rb:40:in `run_command!'
    from /app/vendor/bundle/ruby/2.1.0/gems/railties-4.1.6/lib/rails/commands.rb:17:in `<top (required)>'

[ankane]

The master branch now has a timeout option. You can create an initializer with Searchkick.timeout = 10 if you need to give it more time.

[diasks2]

Thanks. I just tried that (set to 10 and then 25) but I am still getting timeout errors:

Faraday::TimeoutError: Operation timed out after 25000 milliseconds with 0 bytes received

However, it doesn't seem to happen all the time (although I can not yet reproduce what, if anything is different, when it works). For example, last night I was trying Model.reindex and kept getting the timeout errors. Then I ran heroku run rake searchkick:reindex:all and it worked. This morning I tried that same command again (heroku run rake searchkick:reindex:all) and got a timeout error.

[diasks2]

I forgot to mention, I am using the bonsai add-on on Heroku (https://devcenter.heroku.com/articles/bonsai). As the issue only happens on Heroku (not locally) I wonder if the issue is outside of this gem?

[ankane]

Yeah, sounds like an issue with the server. I'd contact Bonsai and see if they can help debug.

[diasks2]

@ankane thanks for your help and quick responses. Your gem is awesome by the way. I'll leave some more details here in case anyone else runs into this issue. I'm still confused on why some things are working the way they are:

In two separate models I had this searchkick text_middle: [:content]. One model would timeout (Model1) on reindex and the other would be fine (Model2). In my controller I had this (using autocomplete and searching across two models):

def index
  @results = Model1.search(params[:query], index_name: [Model1.searchkick_index.name, Model2.searchkick_index.name], limit: 30, operator: 'or')
end

def autocomplete
  render json: Model1.search(params[:query], index_name: [Model1.searchkick_index.name, Model2.searchkick_index.name], limit: 30, operator: 'or')
end

I changed my models to this: searchkick (i.e. removing text_middle: [:content]) and the timeout issue disappeared. However, I am confused as I am still getting results for my search like before (i.e. text_middle). When I check the actual query searchkick is sending to ES it is the same whether I have the text_middle: [:content] or not. This was not what I expected. So, long story short, it seems to be working by only having searchkick in the model instead of searchkick text_middle: [:content]. I must be misunderstanding how the indexing works those as I would expect these to produce different results.

[ankane]

text_middle greatly increases the index size, so it's possible you were hitting memory limits. Not sure why you would be getting results like before, unless text middle wasn't necessary to begin with.

[diasks2]

Good call. It was the memory limits. If anyone runs into this error on Heroku, you most likely need to upgrade your ES add-on plan to one with higher memory limits.

As for the getting the same results with text_middle and without, still not sure. I'll keep investigating and if need be open a separate issue. I think you can probably close this issue now. Thanks again for your help!

[ankane]

Sounds good, thanks for following up.