Timeout::Error when using with Sidekiq in production

[Mauro Asprea]

Some weird stuff is happening when using running Workers that uses Sunspot. Works just fine in production :S

The error is is Timeout::Error

/home/entretenerse/.rbenv/versions/1.9.3-p194/lib/ruby/1.9.1/net/protocol.rb:146:in `rescue in rbuf_fill'

/home/entretenerse/.rbenv/versions/1.9.3-p194/lib/ruby/1.9.1/net/protocol.rb:140:in `rbuf_fill'

/home/entretenerse/.rbenv/versions/1.9.3-p194/lib/ruby/1.9.1/net/protocol.rb:122:in `readuntil'

/home/entretenerse/.rbenv/versions/1.9.3-p194/lib/ruby/1.9.1/net/protocol.rb:132:in `readline'

/home/entretenerse/.rbenv/versions/1.9.3-p194/lib/ruby/1.9.1/net/http.rb:2562:in `read_status_line'

/home/entretenerse/.rbenv/versions/1.9.3-p194/lib/ruby/1.9.1/net/http.rb:2551:in `read_new'

/home/entretenerse/.rbenv/versions/1.9.3-p194/lib/ruby/1.9.1/net/http.rb:1319:in `block in transport_request'

/home/entretenerse/.rbenv/versions/1.9.3-p194/lib/ruby/1.9.1/net/http.rb:1316:in `catch'

/home/entretenerse/.rbenv/versions/1.9.3-p194/lib/ruby/1.9.1/net/http.rb:1316:in `transport_request'

/home/entretenerse/.rbenv/versions/1.9.3-p194/lib/ruby/1.9.1/net/http.rb:1293:in `request'

/home/entretenerse/.rbenv/versions/1.9.3-p194/lib/ruby/1.9.1/net/http.rb:1286:in `block in request'

/home/entretenerse/.rbenv/versions/1.9.3-p194/lib/ruby/1.9.1/net/http.rb:745:in `start'

/home/entretenerse/.rbenv/versions/1.9.3-p194/lib/ruby/1.9.1/net/http.rb:1284:in `request'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/rsolr-1.0.8/lib/rsolr/connection.rb:15:in `execute'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sunspot-75bee8a0d6aa/sunspot_rails/lib/sunspot/rails/solr_instrumentation.rb:14:in `block in execute_with_as_in

strumentation'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/activesupport-3.2.3/lib/active_support/notifications.rb:123:in `block in instrument'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/activesupport-3.2.3/lib/active_support/notifications/instrumenter.rb:20:in `instrument'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/activesupport-3.2.3/lib/active_support/notifications.rb:123:in `instrument'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sunspot-75bee8a0d6aa/sunspot_rails/lib/sunspot/rails/solr_instrumentation.rb:12:in `execute_with_as_instrumenta

tion'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/rsolr-1.0.8/lib/rsolr/client.rb:166:in `execute'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/rsolr-1.0.8/lib/rsolr/client.rb:161:in `send_and_receive'

(eval):2:in `post'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/rsolr-1.0.8/lib/rsolr/client.rb:67:in `update'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/rsolr-1.0.8/lib/rsolr/client.rb:121:in `delete_by_id'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sunspot-75bee8a0d6aa/sunspot/lib/sunspot/indexer.rb:38:in `remove'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sunspot-75bee8a0d6aa/sunspot/lib/sunspot/session.rb:137:in `block in remove'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sunspot-75bee8a0d6aa/sunspot/lib/sunspot/session.rb:136:in `each'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sunspot-75bee8a0d6aa/sunspot/lib/sunspot/session.rb:136:in `remove'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sunspot-75bee8a0d6aa/sunspot/lib/sunspot/session_proxy/abstract_session_proxy.rb:11:in `remove'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sunspot-75bee8a0d6aa/sunspot/lib/sunspot.rb:410:in `remove'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sunspot-75bee8a0d6aa/sunspot_rails/lib/sunspot/rails/searchable.rb:401:in `solr_remove_from_index'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sunspot-75bee8a0d6aa/sunspot_rails/lib/sunspot/rails/searchable.rb:93:in `block in searchable'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/activesupport-3.2.3/lib/active_support/callbacks.rb:420:in `_run__927479678__destroy__269593573__callbacks'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/activesupport-3.2.3/lib/active_support/callbacks.rb:405:in `__run_callback'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/activesupport-3.2.3/lib/active_support/callbacks.rb:385:in `_run_destroy_callbacks'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/activesupport-3.2.3/lib/active_support/callbacks.rb:81:in `run_callbacks'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/activerecord-3.2.3/lib/active_record/callbacks.rb:254:in `destroy'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/activerecord-3.2.3/lib/active_record/transactions.rb:236:in `block in destroy'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/activerecord-3.2.3/lib/active_record/transactions.rb:295:in `block in with_transaction_returning_status'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/activerecord-3.2.3/lib/active_record/connection_adapters/abstract/database_statements.rb:192:in `transaction'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/activerecord-3.2.3/lib/active_record/transactions.rb:208:in `transaction'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/activerecord-3.2.3/lib/active_record/transactions.rb:293:in `with_transaction_returning_status'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/activerecord-3.2.3/lib/active_record/transactions.rb:236:in `destroy'

/home/entretenerse/releases/20120528214114/lib/tasks/data.rake:22:in `block (3 levels) in <top (required)>'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/activerecord-3.2.3/lib/active_record/relation/batches.rb:21:in `block (2 levels) in find_each'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/activerecord-3.2.3/lib/active_record/relation/batches.rb:21:in `each'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/activerecord-3.2.3/lib/active_record/relation/batches.rb:21:in `block in find_each'

/home/entretenerse/releases/20120528214114/lib/tasks/data.rake:22:in `block (2 levels) in <top (required)>'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/rake-0.9.2.2/lib/rake/task.rb:205:in `call'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/rake-0.9.2.2/lib/rake/task.rb:205:in `block in execute'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/rake-0.9.2.2/lib/rake/task.rb:200:in `each'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/rake-0.9.2.2/lib/rake/task.rb:200:in `execute'

/home/entretenerse/releases/20120528214114/app/workers/rake_worker.rb:8:in `perform'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/processor.rb:35:in `block (3 levels) in process'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/middleware/chain.rb:75:in `call'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/middleware/chain.rb:75:in `block in invoke'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/middleware/server/unique_jobs.rb:6:in `call'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/middleware/chain.rb:77:in `block in invoke'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/middleware/server/timeout.rb:14:in `call'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/middleware/chain.rb:77:in `block in invoke'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/middleware/server/active_record.rb:6:in `call'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/middleware/chain.rb:77:in `block in invoke'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/middleware/server/retry_jobs.rb:42:in `call'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/middleware/chain.rb:77:in `block in invoke'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/logging.rb:22:in `with_context'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/middleware/server/logging.rb:7:in `call'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/middleware/chain.rb:77:in `block in invoke'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/middleware/server/exception_handler.rb:9:in `call'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/middleware/chain.rb:77:in `block in invoke'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/middleware/chain.rb:80:in `call'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/middleware/chain.rb:80:in `invoke'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/processor.rb:34:in `block (2 levels) in process'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/processor.rb:65:in `stats'

/home/entretenerse/shared/bundle/ruby/1.9.1/bundler/gems/sidekiq-b486fcf6e000/lib/sidekiq/processor.rb:33:in `block in process'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/celluloid-0.10.0/lib/celluloid/calls.rb:56:in `call'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/celluloid-0.10.0/lib/celluloid/calls.rb:56:in `dispatch'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/celluloid-0.10.0/lib/celluloid/future.rb:18:in `block in initialize'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/celluloid-0.10.0/lib/celluloid/thread_pool.rb:46:in `call'

/home/entretenerse/shared/bundle/ruby/1.9.1/gems/celluloid-0.10.0/lib/celluloid/thread_pool.rb:46:in `block in create'

I've tried increasing the open_timeout and read_timeout but no luck at all.

It actually seems some threading error, but the weird thing is that I'm using sunspot configured via a rake environment so the Sunspot Session should be "thread safe" (ThreadLocalSessionProxy) right? Or should I try to force to re-setup the session?

Please any idea would help :D

This is the code of the worker

class RakeWorker

  include Sidekiq::Worker

  def perform(name)

    args = Rake.application.parse_task_string(name)

    task = Rake::Task[ args.first ]

    task.execute( Rake::TaskArguments.new( task.arg_names, args.last) )    

  end

end

And the I call it lie this:

RakeWorker.perform_async('data:destroy_old')

That rake tasks does something like this:

  desc "Destroy old events"

  task :destroy_old, [:seconds] => :environment do |t, args|

    args.with_defaults(:seconds => 14.days)

    ago = Time.current.ago args.seconds.to_i

    Event.where(['updated_at < ? and date_start < ?', ago, ago]).find_each do |e| 

      e.destroy

      Sunspot.commit_if_delete_dirty

    end

    Event.fold.find_each do |e| 

      e.destroy if e.children_count < 1

      Sunspot.commit_if_delete_dirty

    end

  end

And the trace says it timeouts in the first interaction with sunspot, 'e.destroy'

[Mauro Asprea]

Very rare thing. This was caused because the Solr index was Locked. So I had to add 

<unlockOnStartup>true</unlockOnStartup>

And restart Solr

Does anyone know what causes Solr to lock the index? I'm running a single instance of Solr agains a couple of multithreaded ruby processes that access it with sunspot.