Can't figure out how to rescue ActiveRecord::StatementInvalid error in Rails

Question

I'm using Postgres full-text search and when someone types in a query that's unquery-able, I can't seem to rescue that error. Here's the error I'll get for an example:

    Started GET "/products/search?query=asd+()" for 127.0.0.1 at 2014-02-04 07:46:52 -0600
Processing by ProductsController#search as JSON
  Parameters: {"query"=>"asd ()"}
  User Load (0.6ms)  SELECT "users".* FROM "users" WHERE "users"."id" = 1364 LIMIT 1
  Account Load (0.6ms)  SELECT "accounts".* FROM "accounts" WHERE "accounts"."id" = 2051 LIMIT 1
  Product Load (4.0ms)  SELECT id, brand, style_description, style_number, price_per FROM "products" WHERE (to_tsvector('english', style_description) @@ to_tsquery('asd & ():*') or to_tsvector('english', style_number) @@ to_tsquery('asd & ():*') or to_tsvector('english', brand) @@ to_tsquery('asd & ():*')) AND (account_id = 2051) LIMIT 8
PG::SyntaxError: ERROR:  syntax error in tsquery: "asd & ():*"
: SELECT  id, brand, style_description, style_number, price_per FROM "products"  WHERE (to_tsvector('english', style_description) @@ to_tsquery('asd & ():*') or to_tsvector('english', style_number) @@ to_tsquery('asd & ():*') or to_tsvector('english', brand) @@ to_tsquery('asd & ():*')) AND (account_id = 2051) LIMIT 8
Completed 500 Internal Server Error in 443ms

ActiveRecord::StatementInvalid - PG::SyntaxError: ERROR:  syntax error in tsquery: "asd & ():*"
: SELECT  id, brand, style_description, style_number, price_per FROM "products"  WHERE (to_tsvector('english', style_description) @@ to_tsquery('asd & ():*') or to_tsvector('english', style_number) @@ to_tsquery('asd & ():*') or to_tsvector('english', brand) @@ to_tsquery('asd & ():*')) AND (account_id = 2051) LIMIT 8:
  activerecord (3.2.14) lib/active_record/connection_adapters/abstract_adapter.rb:285:in `rescue in log'
  activerecord (3.2.14) lib/active_record/connection_adapters/abstract_adapter.rb:280:in `log'
  newrelic_rpm (3.7.1.188) lib/new_relic/agent/instrumentation/active_record.rb:46:in `block in log_with_newrelic_instrumentation'
  newrelic_rpm (3.7.1.188) lib/new_relic/agent/method_tracer.rb:276:in `trace_execution_scoped'
  newrelic_rpm (3.7.1.188) lib/new_relic/agent/instrumentation/active_record.rb:43:in `log_with_newrelic_instrumentation'
  activerecord (3.2.14) lib/active_record/connection_adapters/postgresql_adapter.rb:659:in `exec_query'
  activerecord (3.2.14) lib/active_record/connection_adapters/postgresql_adapter.rb:1262:in `select'
  activerecord (3.2.14) lib/active_record/connection_adapters/abstract/database_statements.rb:18:in `select_all'
  activerecord (3.2.14) lib/active_record/connection_adapters/abstract/query_cache.rb:61:in `block in select_all'
  activerecord (3.2.14) lib/active_record/connection_adapters/abstract/query_cache.rb:75:in `cache_sql'
  activerecord (3.2.14) lib/active_record/connection_adapters/abstract/query_cache.rb:61:in `select_all'
  activerecord (3.2.14) lib/active_record/querying.rb:38:in `block in find_by_sql'
  activerecord (3.2.14) lib/active_record/explain.rb:41:in `logging_query_plan'
  activerecord (3.2.14) lib/active_record/querying.rb:37:in `find_by_sql'
  newrelic_rpm (3.7.1.188) lib/new_relic/agent/method_tracer.rb:524:in `block in find_by_sql_with_trace_ActiveRecord_self_name_find_by_sql'
  newrelic_rpm (3.7.1.188) lib/new_relic/agent/method_tracer.rb:276:in `trace_execution_scoped'
  newrelic_rpm (3.7.1.188) lib/new_relic/agent/method_tracer.rb:519:in `find_by_sql_with_trace_ActiveRecord_self_name_find_by_sql'
  activerecord (3.2.14) lib/active_record/relation.rb:171:in `exec_queries'
  activerecord (3.2.14) lib/active_record/relation.rb:160:in `block in to_a'
  activerecord (3.2.14) lib/active_record/explain.rb:41:in `logging_query_plan'
  activerecord (3.2.14) lib/active_record/relation.rb:159:in `to_a'
  bullet (4.7.1) lib/bullet/active_record3x.rb:10:in `to_a'
  activerecord (3.2.14) lib/active_record/relation.rb:198:in `as_json'
  activesupport (3.2.14) lib/active_support/json/encoding.rb:47:in `block in encode'
  activesupport (3.2.14) lib/active_support/json/encoding.rb:77:in `check_for_circular_references'
  activesupport (3.2.14) lib/active_support/json/encoding.rb:46:in `encode'
  activesupport (3.2.14) lib/active_support/json/encoding.rb:31:in `encode'
  activesupport (3.2.14) lib/active_support/core_ext/object/to_json.rb:16:in `to_json'
  app/controllers/products_controller.rb:7:in `search'
  actionpack (3.2.14) lib/action_controller/metal/implicit_render.rb:4:in `send_action'
  actionpack (3.2.14) lib/abstract_controller/base.rb:167:in `process_action'
  actionpack (3.2.14) lib/action_controller/metal/rendering.rb:10:in `process_action'
  actionpack (3.2.14) lib/abstract_controller/callbacks.rb:18:in `block in process_action'
  activesupport (3.2.14) lib/active_support/callbacks.rb:447:in `_run__70639927732585872__process_action__2788875327411416872__callbacks'
  activesupport (3.2.14) lib/active_support/callbacks.rb:405:in `__run_callback'
  activesupport (3.2.14) lib/active_support/callbacks.rb:385:in `_run_process_action_callbacks'
  activesupport (3.2.14) lib/active_support/callbacks.rb:81:in `run_callbacks'
  actionpack (3.2.14) lib/abstract_controller/callbacks.rb:17:in `process_action'
  actionpack (3.2.14) lib/action_controller/metal/rescue.rb:29:in `process_action'
  actionpack (3.2.14) lib/action_controller/metal/instrumentation.rb:30:in `block in process_action'
  activesupport (3.2.14) lib/active_support/notifications.rb:123:in `block in instrument'
  activesupport (3.2.14) lib/active_support/notifications/instrumenter.rb:20:in `instrument'
  activesupport (3.2.14) lib/active_support/notifications.rb:123:in `instrument'
  actionpack (3.2.14) lib/action_controller/metal/instrumentation.rb:29:in `process_action'
  actionpack (3.2.14) lib/action_controller/metal/params_wrapper.rb:207:in `process_action'
  activerecord (3.2.14) lib/active_record/railties/controller_runtime.rb:18:in `process_action'
  newrelic_rpm (3.7.1.188) lib/new_relic/agent/instrumentation/rails3/action_controller.rb:38:in `block in process_action'
  newrelic_rpm (3.7.1.188) lib/new_relic/agent/instrumentation/controller_instrumentation.rb:339:in `perform_action_with_newrelic_trace'
  newrelic_rpm (3.7.1.188) lib/new_relic/agent/instrumentation/rails3/action_controller.rb:37:in `process_action'
  actionpack (3.2.14) lib/abstract_controller/base.rb:121:in `process'
  actionpack (3.2.14) lib/abstract_controller/rendering.rb:45:in `process'
  actionpack (3.2.14) lib/action_controller/metal.rb:203:in `dispatch'
  actionpack (3.2.14) lib/action_controller/metal/rack_delegation.rb:14:in `dispatch'
  actionpack (3.2.14) lib/action_controller/metal.rb:246:in `block in action'
  actionpack (3.2.14) lib/action_dispatch/routing/route_set.rb:73:in `dispatch'
  actionpack (3.2.14) lib/action_dispatch/routing/route_set.rb:36:in `call'
  journey (1.0.4) lib/journey/router.rb:68:in `block in call'
  journey (1.0.4) lib/journey/router.rb:56:in `call'
  actionpack (3.2.14) lib/action_dispatch/routing/route_set.rb:608:in `call'
  newrelic_rpm (3.7.1.188) lib/new_relic/rack/error_collector.rb:50:in `call'
  newrelic_rpm (3.7.1.188) lib/new_relic/rack/agent_hooks.rb:28:in `call'
  newrelic_rpm (3.7.1.188) lib/new_relic/rack/browser_monitoring.rb:23:in `call'
  newrelic_rpm (3.7.1.188) lib/new_relic/rack/developer_mode.rb:42:in `call'
  meta_request (0.2.8) lib/meta_request/middlewares/app_request_handler.rb:13:in `call'
  rack-contrib (1.1.0) lib/rack/contrib/response_headers.rb:17:in `call'
  meta_request (0.2.8) lib/meta_request/middlewares/headers.rb:16:in `call'
  meta_request (0.2.8) lib/meta_request/middlewares/meta_request_handler.rb:13:in `call'
  bullet (4.7.1) lib/bullet/rack.rb:12:in `call'
  rack-cors (0.2.9) lib/rack/cors.rb:54:in `call'
  oink (0.10.1) lib/oink/middleware.rb:17:in `call'
  rack-openid (1.4.2) lib/rack/openid.rb:98:in `call'
  rack (1.4.5) lib/rack/deflater.rb:13:in `call'
  client_side_validations (3.2.6) lib/client_side_validations/middleware.rb:17:in `call'
  warden (1.2.3) lib/warden/manager.rb:35:in `block in call'
  warden (1.2.3) lib/warden/manager.rb:34:in `call'
  actionpack (3.2.14) lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'
  rack (1.4.5) lib/rack/etag.rb:23:in `call'
  rack (1.4.5) lib/rack/conditionalget.rb:25:in `call'
  actionpack (3.2.14) lib/action_dispatch/middleware/head.rb:14:in `call'
  actionpack (3.2.14) lib/action_dispatch/middleware/params_parser.rb:21:in `call'
  actionpack (3.2.14) lib/action_dispatch/middleware/flash.rb:242:in `call'
  rack (1.4.5) lib/rack/session/abstract/id.rb:210:in `context'
  rack (1.4.5) lib/rack/session/abstract/id.rb:205:in `call'
  actionpack (3.2.14) lib/action_dispatch/middleware/cookies.rb:341:in `call'
  activerecord (3.2.14) lib/active_record/query_cache.rb:64:in `call'
  activerecord (3.2.14) lib/active_record/connection_adapters/abstract/connection_pool.rb:479:in `call'
  actionpack (3.2.14) lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
  activesupport (3.2.14) lib/active_support/callbacks.rb:405:in `_run__2432337498521717412__call__41636529287313326__callbacks'
  activesupport (3.2.14) lib/active_support/callbacks.rb:405:in `__run_callback'
  activesupport (3.2.14) lib/active_support/callbacks.rb:385:in `_run_call_callbacks'
  activesupport (3.2.14) lib/active_support/callbacks.rb:81:in `run_callbacks'
  actionpack (3.2.14) lib/action_dispatch/middleware/callbacks.rb:27:in `call'
  rails-dev-tweaks (1.1.0) lib/rails_dev_tweaks/granular_autoload/middleware.rb:34:in `call'
  actionpack (3.2.14) lib/action_dispatch/middleware/remote_ip.rb:31:in `call'
  better_errors (1.1.0) lib/better_errors/middleware.rb:84:in `protected_app_call'
  better_errors (1.1.0) lib/better_errors/middleware.rb:79:in `better_errors_call'
  better_errors (1.1.0) lib/better_errors/middleware.rb:56:in `call'
  airbrake (3.1.15) lib/airbrake/rails/middleware.rb:13:in `call'
  actionpack (3.2.14) lib/action_dispatch/middleware/debug_exceptions.rb:16:in `call'
  actionpack (3.2.14) lib/action_dispatch/middleware/show_exceptions.rb:56:in `call'
  railties (3.2.14) lib/rails/rack/logger.rb:32:in `call_app'
  railties (3.2.14) lib/rails/rack/logger.rb:18:in `call'
  quiet_assets (1.0.2) lib/quiet_assets.rb:18:in `call_with_quiet_assets'
  actionpack (3.2.14) lib/action_dispatch/middleware/request_id.rb:22:in `call'
  rack (1.4.5) lib/rack/methodoverride.rb:21:in `call'
  rack (1.4.5) lib/rack/runtime.rb:17:in `call'
  activesupport (3.2.14) lib/active_support/cache/strategy/local_cache.rb:72:in `call'
  rack (1.4.5) lib/rack/lock.rb:15:in `call'
  actionpack (3.2.14) lib/action_dispatch/middleware/static.rb:63:in `call'
  airbrake (3.1.15) lib/airbrake/user_informer.rb:16:in `_call'
  airbrake (3.1.15) lib/airbrake/user_informer.rb:12:in `call'
  railties (3.2.14) lib/rails/engine.rb:484:in `call'
  railties (3.2.14) lib/rails/application.rb:231:in `call'
  rack (1.4.5) lib/rack/content_length.rb:14:in `call'
  railties (3.2.14) lib/rails/rack/log_tailer.rb:17:in `call'
  thin (1.6.1) lib/thin/connection.rb:82:in `block in pre_process'
  thin (1.6.1) lib/thin/connection.rb:80:in `pre_process'
  thin (1.6.1) lib/thin/connection.rb:55:in `process'
  thin (1.6.1) lib/thin/connection.rb:41:in `receive_data'
  eventmachine (1.0.3) lib/eventmachine.rb:187:in `run'
  thin (1.6.1) lib/thin/backends/base.rb:73:in `start'
  thin (1.6.1) lib/thin/server.rb:162:in `start'
  rack (1.4.5) lib/rack/handler/thin.rb:13:in `run'
  rack (1.4.5) lib/rack/server.rb:268:in `start'
  railties (3.2.14) lib/rails/commands/server.rb:70:in `start'
  railties (3.2.14) lib/rails/commands.rb:55:in `block in <top (required)>'
  railties (3.2.14) lib/rails/commands.rb:50:in `<top (required)>'
  script/rails:6:in `<main>'

Here's my code:

 def self.text_search(query, account)
  uncached do 
   if query.present?
    begin
      query = query.split(" ").join(" & ")
      if account.use_global_products?
        where("to_tsvector('english', style_description) @@ to_tsquery(:q) or to_tsvector('english', style_number) @@ to_tsquery(:q) or to_tsvector('english', brand) @@ to_tsquery(:q)", q: "#{query.strip}:*").where("account_id = ? OR account_id = ?", 0, account.id)
      else
        where("to_tsvector('english', style_description) @@ to_tsquery(:q) or to_tsvector('english', style_number) @@ to_tsquery(:q) or to_tsvector('english', brand) @@ to_tsquery(:q)", q: "#{query.strip}:*").where("account_id = ?", account.id)
      end
    rescue Exception => error
      puts "inspect it #{error.inspect}"
    end
  else
    scoped
  end
end

end

Any idea why ActiveRecord::StatementInvalid still isn't rescuing?

Answer 1

I had a similar issue in one of my projects. I was able to rescue the error thanks to @Tyler's answer.

I'm using Rails 5.2.3. In my database there is a table, Movie, with one column called title in it.

(Please forgive the use of eval, I know you it's bad practice to use it.)

begin
  result = eval("Movie.where(name: \"test\")")
  p result # this actually triggers the SQL error
rescue ActiveRecord::StatementInvalid => error_variable
  p "We got 'em"
  result = error_variable.to_s
end

So in short, you can't just run the query in the begin block, you also need to evaluate it. This can be done with a simple p statement of the query result.

Answer 2

Here is the code (using rails 4.0.1 here) in abstract_adapter.rb that handles the output to log (inside log method)

  rescue => e
    message = "#{e.class.name}: #{e.message}: #{sql}"
    @logger.error message if @logger
    exception = translate_exception(e, message)
    exception.set_backtrace e.backtrace
    raise exception
  end

Looks like as long as @logger is active activerecord will always report this to the log file.

I wish there was a way to avoid this kind of behaviour when rescuing externally, so any ideas would be welcome.

Answer 3

EDIT

This looks like it has to do with when the query is actually evaluated. You're returning the chained query, but it's likely being first executed in your controller, since you're not returning the actual results of the query with your method.

So you could either rescue in the controller, or you could go ahead and evaluate the query in your method and then return the object you want.

Also note that it's not a great idea to rescue Exception in Ruby. See Why is it a bad style to `rescue Exception => e` in Ruby? for more

---

You don't need to structure it the way you have (begin/rescue/end); you can rescue off the entire method failing instead:

def self.text_search(query)
  uncached do 
    if query.present?
      query = query.split(" ").join(" & ")
      where("to_tsvector('english', style_description) @@ to_tsquery(:q) or to_tsvector('english', style_number) @@ to_tsquery(:q) or to_tsvector('english', brand) @@ to_tsquery(:q)", q: "#{query.strip}:*").where("account_id = ? OR account_id = ?", 0, account.id)
    else
      scoped
    end
  end
rescue ActiveRecord::StatementInvalid => error
  puts "Search Error"
end