Could not log "warn.thinking_sphinx" event. NoMethodError: undefined method `payload'

[JasonBarnabe]

Ruby 2.4.2 Sphinx 2.2.11-id64-release Rails 5.1.4 Full code: https://github.com/JasonBarnabe/greasyfork/tree/0f3fac2bb13e52552c43d182c55c948ce39bfa97

After upgrade of thinking-sphinx from 3.3.0 to 3.4.1, upon performing any search, I receive this in the log (the search seemingly works fine):

E, [2017-09-24T17:06:22.957975 #9683] ERROR -- : Could not log "warn.thinking_sphinx" event. NoMethodError: undefined method `payload' for "  \e[1m\e[32mSphinx\e[0m  ":String
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/thinking-sphinx-3.4.1/lib/thinking_sphinx/active_record/log_subscriber.rb:19:in `warn'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/thinking-sphinx-3.4.1/lib/thinking_sphinx/active_record/log_subscriber.rb:19:in `warn'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/subscriber.rb:99:in `finish'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/log_subscriber.rb:83:in `finish'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/notifications/fanout.rb:102:in `finish'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/notifications/fanout.rb:46:in `block in finish'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/notifications/fanout.rb:46:in `each'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/notifications/fanout.rb:46:in `finish'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/notifications/instrumenter.rb:42:in `finish_with_state'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/notifications/instrumenter.rb:27:in `instrument'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/notifications.rb:166:in `instrument'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/thinking-sphinx-3.4.1/lib/thinking_sphinx/logger.rb:3:in `log'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/thinking-sphinx-3.4.1/lib/thinking_sphinx/middlewares/valid_options.rb:16:in `check_options'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/thinking-sphinx-3.4.1/lib/thinking_sphinx/middlewares/valid_options.rb:5:in `block in call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/thinking-sphinx-3.4.1/lib/thinking_sphinx/middlewares/valid_options.rb:5:in `each'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/thinking-sphinx-3.4.1/lib/thinking_sphinx/middlewares/valid_options.rb:5:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/thinking-sphinx-3.4.1/lib/thinking_sphinx/middlewares/stale_id_filter.rb:10:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/middleware-0.1.0/lib/middleware/runner.rb:31:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/middleware-0.1.0/lib/middleware/builder.rb:102:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/thinking-sphinx-3.4.1/lib/thinking_sphinx/search.rb:88:in `populate'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/thinking-sphinx-3.4.1/lib/thinking_sphinx/active_record/base.rb:55:in `merge_search'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/thinking-sphinx-3.4.1/lib/thinking_sphinx/active_record/base.rb:20:in `search'
/home/www/greasyfork/releases/20170924155815/app/controllers/scripts_controller.rb:52:in `index'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_controller/metal/basic_implicit_render.rb:4:in `send_action'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/abstract_controller/base.rb:186:in `process_action'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_controller/metal/rendering.rb:30:in `process_action'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/callbacks.rb:131:in `run_callbacks'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/abstract_controller/callbacks.rb:19:in `process_action'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_controller/metal/rescue.rb:20:in `process_action'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/notifications.rb:166:in `block in instrument'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/notifications.rb:166:in `instrument'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_controller/metal/params_wrapper.rb:252:in `process_action'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activerecord-5.1.4/lib/active_record/railties/controller_runtime.rb:22:in `process_action'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/abstract_controller/base.rb:124:in `process'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionview-5.1.4/lib/action_view/rendering.rb:30:in `process'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_controller/metal.rb:189:in `dispatch'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_controller/metal.rb:253:in `dispatch'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/routing/route_set.rb:49:in `dispatch'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/routing/route_set.rb:31:in `serve'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/journey/router.rb:50:in `block in serve'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/journey/router.rb:33:in `each'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/journey/router.rb:33:in `serve'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/routing/route_set.rb:834:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/omniauth-1.6.1/lib/omniauth/strategy.rb:189:in `call!'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/omniauth-1.6.1/lib/omniauth/strategy.rb:167:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/omniauth-1.6.1/lib/omniauth/strategy.rb:189:in `call!'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/omniauth-1.6.1/lib/omniauth/strategy.rb:167:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/omniauth-1.6.1/lib/omniauth/b
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/abstract_controller/base.rb:124:in `process'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionview-5.1.4/lib/action_view/rendering.rb:30:in `process'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_controller/metal.rb:189:in `dispatch'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_controller/metal.rb:253:in `dispatch'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/routing/route_set.rb:49:in `dispatch'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/routing/route_set.rb:31:in `serve'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/journey/router.rb:50:in `block in serve'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/journey/router.rb:33:in `each'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/journey/router.rb:33:in `serve'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/routing/route_set.rb:834:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/omniauth-1.6.1/lib/omniauth/strategy.rb:189:in `call!'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/omniauth-1.6.1/lib/omniauth/strategy.rb:167:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/omniauth-1.6.1/lib/omniauth/strategy.rb:189:in `call!'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/omniauth-1.6.1/lib/omniauth/strategy.rb:167:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/omniauth-1.6.1/lib/omniauth/builder.rb:63:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/rack/agent_hooks.rb:30:in `traced_call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/rack/browser_monitoring.rb:32:in `traced_call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/warden-1.2.7/lib/warden/manager.rb:36:in `block in call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/warden-1.2.7/lib/warden/manager.rb:35:in `catch'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/warden-1.2.7/lib/warden/manager.rb:35:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/rack-2.0.3/lib/rack/etag.rb:25:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/rack-2.0.3/lib/rack/conditional_get.rb:25:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/rack-2.0.3/lib/rack/head.rb:12:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/rack-2.0.3/lib/rack/session/abstract/id.rb:232:in `context'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/rack-2.0.3/lib/rack/session/abstract/id.rb:226:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/middleware/cookies.rb:613:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/middleware/callbacks.rb:26:in `block in call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/callbacks.rb:97:in `run_callbacks'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/middleware/callbacks.rb:24:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/middleware/debug_exceptions.rb:59:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/railties-5.1.4/lib/rails/rack/logger.rb:36:in `call_app'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/railties-5.1.4/lib/rails/rack/logger.rb:24:in `block in call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/tagged_logging.rb:69:in `block in tagged'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/tagged_logging.rb:26:in `tagged'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/tagged_logging.rb:69:in `tagged'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/railties-5.1.4/lib/rails/rack/logger.rb:24:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/middleware/request_id.rb:25:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/rack-2.0.3/lib/rack/method_override.rb:22:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/rack-2.0.3/lib/rack/runtime.rb:22:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/activesupport-5.1.4/lib/active_support/cache/strategy/local_cache_middleware.rb:27:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/actionpack-5.1.4/lib/action_dispatch/middleware/executor.rb:12:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/rack-2.0.3/lib/rack/sendfile.rb:111:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/railties-5.1.4/lib/rails/engine.rb:522:in `call'
/home/www/greasyfork/shared/bundle/ruby/2.4.0/gems/newrelic_rpm-4.4.0.336/lib/new_relic/agent/instrumentation/middleware_tracing.rb:92:in `call'
/home/www/.rvm/gems/ruby-2.4.2/gems/passenger-5.1.8/src/ruby_supportlib/phusion_passenger/rack/thread_handler_extension.rb:97:in `process_request'
/home/www/.rvm/gems/ruby-2.4.2/gems/passenger-5.1.8/src/ruby_supportlib/phusion_passenger/request_handler/thread_handler.rb:152:in `accept_and_process_next_request'
/home/www/.rvm/gems/ruby-2.4.2/gems/passenger-5.1.8/src/ruby_supportlib/phusion_passenger/request_handler/thread_handler.rb:113:in `main_loop'
/home/www/.rvm/gems/ruby-2.4.2/gems/passenger-5.1.8/src/ruby_supportlib/phusion_passenger/request_handler.rb:416:in `block (3 levels) in start_threads'
/home/www/.rvm/gems/ruby-2.4.2/gems/passenger-5.1.8/src/ruby_supportlib/phusion_passenger/utils.rb:113:in `block in create_thread_and_abort_on_exception'

[pat]

Thanks Jason, just pushed a fix for this in 60df63108b6a67b9740f8b277886526d8aa79738, which you can use from the develop branch if you wish.

It's worth noting the underlying warning is caused by invalid search options in the search call - so if you don't want to use the develop branch, it's worth double-checking the options you're passing through - fix that up and you'll avoid seeing the lengthy error in your logs. I'll look at pushing a new patch release in the coming week or so.

[pat]

FWIW, 3.4.2 is now released with a fix for this.

Also, I found out that some valid options weren't covered in my validation, so it's quite possible you weren't using anything invalid to begin with!

[JasonBarnabe]

Thanks, this worked. Turns out the offending option was match_mode, which I found is no longer used.