Sphinx error in passenger, works in console

[mrmanishs]

Whenever I try to do anything in my app through passenger, I get an error similar to this:

F, [2018-03-07T21:35:13.949318 #30762] FATAL -- : [d6484d23-620d-4f33-8f17-13c12b7dab53] Riddle::CommandFailedError (Sphinx command failed to execute):
F, [2018-03-07T21:35:13.949426 #30762] FATAL -- : [d6484d23-620d-4f33-8f17-13c12b7dab53]  
F, [2018-03-07T21:35:13.949536 #30762] FATAL -- : [d6484d23-620d-4f33-8f17-13c12b7dab53] app/controllers/listing_controller.rb:


That's all I get... no other information.

The same instructions work in console and there are no issues. Everything else on the rails app works fine.

Any idea? What else can I do to get more information?

Manish

[mrmanishs]

Correction whenever I try to do anything app through passenger utilizing sphinx.

[mrmanishs]

Here's an exception:

D, [2018-03-07T23:15:35.404762 #3912] DEBUG -- : [aa8081bd-8b94-4dbf-895e-21263722a767] ["/usr/local/rvm/gems/ruby-2.3.3/gems/riddle-2.3.0/lib/riddle/execute_command.rb:25:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/riddle-2.3.0/lib/riddle/execute_command.rb:7:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/riddle-2.3.0/lib/riddle/controller.rb:33:in `index'", "/usr/local/rvm/gems/ruby-2.3.3/gems/thinking-sphinx-3.4.2/lib/thinking_sphinx/controller.rb:8:in `block (2 levels) in index'", "/usr/local/rvm/gems/ruby-2.3.3/gems/thinking-sphinx-3.4.2/lib/thinking_sphinx/guard/files.rb:14:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/thinking-sphinx-3.4.2/lib/thinking_sphinx/guard/files.rb:3:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/thinking-sphinx-3.4.2/lib/thinking_sphinx/controller.rb:7:in `block in index'", "/usr/local/rvm/gems/ruby-2.3.3/gems/thinking-sphinx-3.4.2/lib/thinking_sphinx/indexing_strategies/all_at_once.rb:5:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/thinking-sphinx-3.4.2/lib/thinking_sphinx/controller.rb:6:in `index'", "/usr/local/rvm/gems/ruby-2.3.3/gems/thinking-sphinx-3.4.2/lib/thinking_sphinx/deltas/index_job.rb:7:in `perform'", "/usr/local/rvm/gems/ruby-2.3.3/gems/thinking-sphinx-3.4.2/lib/thinking_sphinx/deltas/default_delta.rb:21:in `index'", "/usr/local/rvm/gems/ruby-2.3.3/gems/thinking-sphinx-3.4.2/lib/thinking_sphinx/active_record/callbacks/delta_callbacks.rb:10:in `block in after_commit'", "/usr/local/rvm/gems/ruby-2.3.3/gems/thinking-sphinx-3.4.2/lib/thinking_sphinx/active_record/callbacks/delta_callbacks.rb:9:in `each'", "/usr/local/rvm/gems/ruby-2.3.3/gems/thinking-sphinx-3.4.2/lib/thinking_sphinx/active_record/callbacks/delta_callbacks.rb:9:in `after_commit'", "/usr/local/rvm/gems/ruby-2.3.3/gems/thinking-sphinx-3.4.2/lib/thinking_sphinx/callbacks.rb:7:in `block (2 levels) in callbacks'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activesupport-5.1.5/lib/active_support/callbacks.rb:413:in `block in make_lambda'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activesupport-5.1.5/lib/active_support/callbacks.rb:270:in `block in simple'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activesupport-5.1.5/lib/active_support/callbacks.rb:511:in `block in invoke_after'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activesupport-5.1.5/lib/active_support/callbacks.rb:511:in `each'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activesupport-5.1.5/lib/active_support/callbacks.rb:511:in `invoke_after'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activesupport-5.1.5/lib/active_support/callbacks.rb:132:in `run_callbacks'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activesupport-5.1.5/lib/active_support/callbacks.rb:827:in `_run_commit_callbacks'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activerecord-5.1.5/lib/active_record/transactions.rb:343:in `committed!'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activerecord-5.1.5/lib/active_record/connection_adapters/abstract/transaction.rb:93:in `block in commit_records'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activerecord-5.1.5/lib/active_record/connection_adapters/abstract/transaction.rb:93:in `each'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activerecord-5.1.5/lib/active_record/connection_adapters/abstract/transaction.rb:93:in `ensure in commit_records'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activerecord-5.1.5/lib/active_record/connection_adapters/abstract/transaction.rb:93:in `commit_records'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activerecord-5.1.5/lib/active_record/connection_adapters/abstract/transaction.rb:178:in `block in commit_transaction'", "/usr/local/rvm/rubies/ruby-2.3.3/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activerecord-5.1.5/lib/active_record/connection_adapters/abstract/transaction.rb:168:in `commit_transaction'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activerecord-5.1.5/lib/active_record/connection_adapters/abstract/transaction.rb:207:in `block in within_new_transaction'", "/usr/local/rvm/rubies/ruby-2.3.3/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activerecord-5.1.5/lib/active_record/connection_adapters/abstract/transaction.rb:191:in `within_new_transaction'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activerecord-5.1.5/lib/active_record/connection_adapters/abstract/database_statements.rb:235:in `transaction'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activerecord-5.1.5/lib/active_record/transactions.rb:210:in `transaction'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activerecord-5.1.5/lib/active_record/transactions.rb:381:in `with_transaction_returning_status'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activerecord-5.1.5/lib/active_record/transactions.rb:308:in `block in save'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activerecord-5.1.5/lib/active_record/transactions.rb:323:in `rollback_active_record_state!'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activerecord-5.1.5/lib/active_record/transactions.rb:307:in `save'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activerecord-5.1.5/lib/active_record/suppressor.rb:42:in `save'", "/sites/cap/classifieds.acceleweb.com/app/controllers/listing_controller.rb:819:in `toggle_active'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_controller/metal/basic_implicit_render.rb:4:in `send_action'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/abstract_controller/base.rb:186:in `process_action'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_controller/metal/rendering.rb:30:in `process_action'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/abstract_controller/callbacks.rb:20:in `block in process_action'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activesupport-5.1.5/lib/active_support/callbacks.rb:131:in `run_callbacks'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/abstract_controller/callbacks.rb:19:in `process_action'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_controller/metal/rescue.rb:20:in `process_action'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activesupport-5.1.5/lib/active_support/notifications.rb:166:in `block in instrument'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activesupport-5.1.5/lib/active_support/notifications/instrumenter.rb:21:in `instrument'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activesupport-5.1.5/lib/active_support/notifications.rb:166:in `instrument'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_controller/metal/instrumentation.rb:30:in `process_action'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_controller/metal/params_wrapper.rb:252:in `process_action'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activerecord-5.1.5/lib/active_record/railties/controller_runtime.rb:22:in `process_action'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/abstract_controller/base.rb:124:in `process'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionview-5.1.5/lib/action_view/rendering.rb:30:in `process'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_controller/metal.rb:189:in `dispatch'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_controller/metal.rb:253:in `dispatch'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_dispatch/routing/route_set.rb:49:in `dispatch'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_dispatch/routing/route_set.rb:31:in `serve'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_dispatch/journey/router.rb:50:in `block in serve'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_dispatch/journey/router.rb:33:in `each'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_dispatch/journey/router.rb:33:in `serve'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_dispatch/routing/route_set.rb:844:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/rack-2.0.4/lib/rack/etag.rb:25:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/rack-2.0.4/lib/rack/conditional_get.rb:25:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/rack-2.0.4/lib/rack/head.rb:12:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/rack-2.0.4/lib/rack/session/abstract/id.rb:232:in `context'", "/usr/local/rvm/gems/ruby-2.3.3/gems/rack-2.0.4/lib/rack/session/abstract/id.rb:226:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_dispatch/middleware/cookies.rb:613:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_dispatch/middleware/callbacks.rb:26:in `block in call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activesupport-5.1.5/lib/active_support/callbacks.rb:97:in `run_callbacks'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_dispatch/middleware/callbacks.rb:24:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_dispatch/middleware/debug_exceptions.rb:59:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/railties-5.1.5/lib/rails/rack/logger.rb:36:in `call_app'", "/usr/local/rvm/gems/ruby-2.3.3/gems/railties-5.1.5/lib/rails/rack/logger.rb:24:in `block in call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activesupport-5.1.5/lib/active_support/tagged_logging.rb:69:in `block in tagged'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activesupport-5.1.5/lib/active_support/tagged_logging.rb:26:in `tagged'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activesupport-5.1.5/lib/active_support/tagged_logging.rb:69:in `tagged'", "/usr/local/rvm/gems/ruby-2.3.3/gems/railties-5.1.5/lib/rails/rack/logger.rb:24:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_dispatch/middleware/remote_ip.rb:79:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/request_store-1.4.0/lib/request_store/middleware.rb:19:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_dispatch/middleware/request_id.rb:25:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/rack-2.0.4/lib/rack/method_override.rb:22:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/rack-2.0.4/lib/rack/runtime.rb:22:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/activesupport-5.1.5/lib/active_support/cache/strategy/local_cache_middleware.rb:27:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/actionpack-5.1.5/lib/action_dispatch/middleware/executor.rb:12:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/rack-2.0.4/lib/rack/sendfile.rb:111:in `call'", "/usr/local/rvm/gems/ruby-2.3.3/gems/railties-5.1.5/lib/rails/engine.rb:522:in `call'", "/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:97:in `process_request'", "/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:152:in `accept_and_process_next_request'", "/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:113:in `main_loop'", "/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler.rb:416:in `block (3 levels) in start_threads'", "/usr/lib/ruby/vendor_ruby/phusion_passenger/utils.rb:113:in `block in create_thread_and_abort_on_exception'"]

On Wednesday, March 7, 2018 at 4:39:16 PM UTC-5, mrmanishs wrote:

[mrmanishs]

More info, I printed the command result and this is what comes up:

D, [2018-03-08T03:32:30.171310 #17284] DEBUG -- : [250bfa14-0c05-45fd-ae58-3079b1b6f995] Command Result: #<Riddle::CommandResult:0x007f89f74bd498 @output="Sphinx 3.0.2 (commit 2592786)\nCopyright (c) 2001-2018, Andrew Aksyonoff\nCopyright (c) 2008-2016, Sphinx Technologies Inc (http://sphinxsearch.com)\n\nusing config file '/sites/cap/classifieds.acceleweb.com/config/production.sphinx.conf'...\nWARNING: key 'docinfo' was permanently removed from Sphinx configuration. Refer to documentation for details.\nWARNING: key 'docinfo' was permanently removed from Sphinx configuration. Refer to documentation for details.\nindexing index 'address_delta'...\nFATAL: failed to lock /sites/cap/classifieds.acceleweb.com/db/sphinx/production/address_delta.spl: Resource temporarily unavailable, will not index. Try --rotate option.\n", @status=1, @command="/usr/local/bin/indexer --config \"/sites/cap/classifieds.acceleweb.com/config/production.sphinx.conf\" address_delta", @successful=false>

On Wednesday, March 7, 2018 at 4:39:16 PM UTC-5, mrmanishs wrote:

[mrmanishs]

After further investigation, it looks like an issue with delta indexing. Is there a fix? Should real-time indices be used instead, is that a better approach?

On Wednesday, March 7, 2018 at 4:39:16 PM UTC-5, mrmanishs wrote:

[Pat Allan]

Hi Manish,

I’m at a conference today, so please excuse the brevity, but it sounds like this might be a permissions issue. See this note in the documentation:

https://freelancing-gods.com/thinking-sphinx/common_issues.html#deltas

(Both the deltas section and possibly the following section for passenger)

Certainly, real-time indices shouldn’t hit these issues, but you should certainly be able to get your current setup working.

Hope this helps!

— 

Pat

--
You received this message because you are subscribed to the Google Groups "Thinking Sphinx" group.
To unsubscribe from this group and stop receiving emails from it, send an email to thinking-sphi...@googlegroups.com.
To post to this group, send email to thinkin...@googlegroups.com.
Visit this group at https://groups.google.com/group/thinking-sphinx.
For more options, visit https://groups.google.com/d/optout.

[mrmanishs]

Thanks Pat.

- searchd and nginx are both being run as root. Everything's root actually...
- I have searchd in /usr/local/bin and confirmed the production bin_path is /usr/local/bin . I have this in my thinking_sphinx.yml file for prod:

production:
  mysql41: 9401
  configuration_file: "<path_to_config>"
  log: "<path_to_log>"
  query_log: "<path_to_query_log>"
  pid_file: "<path_to_pid_file>"
  min_infix_len: 3
  bin_path: '/usr/local/bin'
  indexed_models:
        - Address
  quiet_deltas: true

Any other thoughts?

[Pat Allan]

Hmm. Is there anything related to this issue in your passenger logs? And/or if you’re using nginx/apache/etc in front of that, their logs?

Unrelated, but: indexed_models is no longer needed/used by TS v3+.

— 

Pat

[mrmanishs]

I have nginx in front of passenger, so all the passenger log entries go into the nginx one. The only item in nginx is the url calls come back with a 500.

Thanks for the note. 

Any other ideas? Also, up for doing some real-time debugging if it would help. I am not really sure what's going on and it's impacting functionality on site :(

[Pat Allan]

Hmm. Have you tried running a rebuild? And has this problem started only recently?

As a stop-gap solution, you could disable deltas and run the `ts:index` task more regularly, but granted, that’s not ideal.

[mrmanishs]

Thanks. I actually migrated to a new server and installed the latest version of Sphinx/TS.

New server: Sphinx 3.0.2, TS 3.4.2 on Rails 5.1.5
Old server: Sphinx 2.2.6, TS 3.2.0 on Rails 4.1.6

Could I have missed something in the upgrade that these symptoms may show?

I have disabled deltas for now to get it going, but it's not ideal.

[Pat Allan]

So, one thing that’s probably changed in that upgrade is that the newer versions of Riddle are now a little fussier about running indexing commands, and raise exceptions depending on the status code of the `indexer` command. So, it could be possible this issue was always happening but the errors weren’t apparent. I feel that’s unlikely though - you’d probably have noticed if delta results weren’t appearing?

Also worth considering is the underlying error:

FATAL: failed to lock /sites/cap/classifieds.acceleweb.com/db/sphinx/production/address_delta.spl: Resource temporarily unavailable, will not index

I presume the path there is correct? What are the permissions on that file? Is the owner root?

— 

Pat

[mrmanishs]

Thanks for getting back Pat. Yes deltas were working great on the old server.

The permission is 644 and owner is root.

To unsubscribe from this group and stop receiving emails from it, send an email to thinking-sphinx+unsub...@googlegroups.com.

[Pat Allan]

I know it’s hard to test now that you’ve disabled deltas, but I wondering… did it happen on every single request?

It’s just that, previously - as already noted - failed indexing didn’t raise exceptions. If two requests came at the same time that both made alterations to the same model, one of the delta processing attempts would work, the other wouldn’t - but the end result is still both alterations would be in Sphinx (the successful processing captured both changes).

Now, in the same scenario, one would work, and the other would fail and raise an exception. The data would still be persisted in Sphinx (and given deltas are invoked in after_commit, in the database as well), but the 500 error resulting from the failure is a terrible user experience.

If this is the situation, then the best solution is to either shift delta processing into a background worker (via ts-sidekiq-delta, ts-delayed-delta, or ts-resque-delta), or to use real-time indices.

Of course, if this isn’t the case - if a single request raises the exception, and there’s no other concurrent requests altering the same model, then the cause will be something else (and I’m really not sure what it could be!). Perhaps real-time indices are worth investigating either way? They’ve been around in TS for a good while now and I use them for any of my new projects that need Sphinx, as do significantly sized Flying Sphinx customers.

[mrmanishs]

Thanks Pat for the follow-up.

Yes, was happening on each and every request. As I stated, it only happened through Passenger also, not through console.

I think I'll switch to real-time indices, if you think of anything else, let me know. It's got me stumped.

[Pat Allan]

I’m still out of ideas for the moment.

But as for real-time indices, this is a good place to start:

https://freelancing-gods.com/thinking-sphinx/real_time.html

— 

Pat

[mrmanishs]

Thanks. I'll go ahead and start implementing this week and let you know if I run into hiccups. If you think of anything else, let me know.