ActiveSupport::Notifications transaction left open

controller_metrics.rb

ActiveSupport::Notifications.subscribe "process_action.action_controller" do |*args|
  event = ActiveSupport::Notifications::Event.new(*args)

  controller = Statsd.sanitized_class(event.payload[:controller].constantize)
  action = event.payload[:action]

  tags = {
    route: "#{controller}:#{action}"
  }

  # If an exception is raised by the controller method, the status will be nil.
  # We will track these separately for now.
  status_xxx = if event.payload[:status]
                 "#{event.payload[:status] / 100}XX"
               else
                 "exception"
               end

  # our featuretoggles are stored in the DB
  if FeatureToggle[:db_log_failed_requests].enabled?
    unless %w(2XX 3XX).include?(status_xxx)
      FailedRequest.upsert!(
        status: status_xxx,
        route: tags[:route],
        params: event.payload[:params].to_h.reject {|k,v| %w(controller action).include?(k) },
        last_seen: Time.now,
        api_host: $api_host_ip
      )
    end
  end
end

class FailedRequest < ActiveRecord::Base
  def self.upsert!(status:, route:, params:, last_seen:, api_host:)
    transaction do
      key = {status: status, route: route, params_hash: params.hash}
      r = where(key).first

      if r.nil?
        r = new(key)
        r.count = 0
      end

      r.count += 1
      r.last_seen = last_seen
      r.params = params
      r.api_host = api_host

      r.save
    end
  end
end

# Test error:
# ApiV2Test#test_grouping_should_fail_if_you_dont_explicitly_specify_fields:
# ActiveRecord::StatementInvalid: PG::InFailedSqlTransaction: ERROR:  current transaction is aborted, commands ignored until end of transaction block
# : SELECT "flipper_gates".* FROM "flipper_gates" WHERE "flipper_gates"."feature_key" = $1
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/postgresql_adapter.rb:622:in `async_exec_prepared'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/postgresql_adapter.rb:622:in `block (2 levels) in exec_cache'
#     vendor/bundle/gems/activesupport-5.2.3/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
#     vendor/bundle/gems/activesupport-5.2.3/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
#     vendor/bundle/gems/activesupport-5.2.3/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/postgresql_adapter.rb:621:in `block in exec_cache'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract_adapter.rb:581:in `block (2 levels) in log'
#     /qc/ruby26/lib64/ruby/2.6.0/monitor.rb:235:in `mon_synchronize'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract_adapter.rb:580:in `block in log'
#     vendor/bundle/gems/activesupport-5.2.3/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract_adapter.rb:571:in `log'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/postgresql_adapter.rb:620:in `exec_cache'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/postgresql_adapter.rb:600:in `execute_and_clear'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/postgresql/database_statements.rb:81:in `exec_query'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/database_statements.rb:482:in `select_prepared'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/database_statements.rb:68:in `select_all'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/query_cache.rb:104:in `block in select_all'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/query_cache.rb:127:in `block in cache_sql'
#     /qc/ruby26/lib64/ruby/2.6.0/monitor.rb:235:in `mon_synchronize'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/query_cache.rb:113:in `cache_sql'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/connection_adapters/abstract/query_cache.rb:104:in `select_all'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/querying.rb:41:in `find_by_sql'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/relation.rb:560:in `block in exec_queries'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/relation.rb:584:in `skip_query_cache_if_necessary'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/relation.rb:547:in `exec_queries'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/relation.rb:422:in `load'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/relation.rb:200:in `records'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/relation/delegation.rb:71:in `each'
#     vendor/bundle/gems/flipper-active_record-0.17.1/lib/flipper/adapters/active_record.rb:200:in `detect'
#     vendor/bundle/gems/flipper-active_record-0.17.1/lib/flipper/adapters/active_record.rb:200:in `block in result_for_feature'
#     vendor/bundle/gems/flipper-active_record-0.17.1/lib/flipper/adapters/active_record.rb:196:in `each'
#     vendor/bundle/gems/flipper-active_record-0.17.1/lib/flipper/adapters/active_record.rb:196:in `result_for_feature'
#     vendor/bundle/gems/flipper-active_record-0.17.1/lib/flipper/adapters/active_record.rb:90:in `get'
#     vendor/bundle/gems/flipper-0.17.1/lib/flipper/adapters/memoizable.rb:71:in `block in get'
#     vendor/bundle/gems/flipper-0.17.1/lib/flipper/adapters/memoizable.rb:71:in `fetch'
#     vendor/bundle/gems/flipper-0.17.1/lib/flipper/adapters/memoizable.rb:71:in `get'
#     vendor/bundle/gems/flipper-0.17.1/lib/flipper/feature.rb:235:in `gate_values'
#     vendor/bundle/gems/flipper-0.17.1/lib/flipper/feature.rb:104:in `block in enabled?'
#     vendor/bundle/gems/flipper-0.17.1/lib/flipper/feature.rb:375:in `block in instrument'
#     vendor/bundle/gems/flipper-0.17.1/lib/flipper/instrumenters/noop.rb:5:in `instrument'
#     vendor/bundle/gems/flipper-0.17.1/lib/flipper/feature.rb:372:in `instrument'
#     vendor/bundle/gems/flipper-0.17.1/lib/flipper/feature.rb:103:in `enabled?'
#     config/initializers/controller_metrics.rb:33:in `block in <top (required)>'
#     vendor/bundle/gems/activesupport-5.2.3/lib/active_support/notifications/fanout.rb:129:in `finish'
#     vendor/bundle/gems/activesupport-5.2.3/lib/active_support/notifications/fanout.rb:48:in `block in finish'
#     vendor/bundle/gems/activesupport-5.2.3/lib/active_support/notifications/fanout.rb:48:in `each'
#     vendor/bundle/gems/activesupport-5.2.3/lib/active_support/notifications/fanout.rb:48:in `finish'
#     vendor/bundle/gems/activesupport-5.2.3/lib/active_support/notifications/instrumenter.rb:44:in `finish_with_state'
#     vendor/bundle/gems/activesupport-5.2.3/lib/active_support/notifications/instrumenter.rb:29:in `instrument'
#     vendor/bundle/gems/activesupport-5.2.3/lib/active_support/notifications.rb:168:in `instrument'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
#     vendor/bundle/gems/activerecord-5.2.3/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
#     vendor/bundle/gems/actionpack-5.2.3/lib/abstract_controller/base.rb:134:in `process'
#     vendor/bundle/gems/actionview-5.2.3/lib/action_view/rendering.rb:32:in `process'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_controller/metal.rb:191:in `dispatch'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_controller/metal.rb:252:in `dispatch'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/routing/route_set.rb:34:in `serve'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/journey/router.rb:52:in `block in serve'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/journey/router.rb:35:in `each'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/journey/router.rb:35:in `serve'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/routing/route_set.rb:840:in `call'
#     vendor/bundle/gems/flipper-0.17.1/lib/flipper/middleware/memoizer.rb:62:in `memoized_call'
#     vendor/bundle/gems/flipper-0.17.1/lib/flipper/middleware/memoizer.rb:40:in `call'
#     vendor/bundle/gems/flipper-0.17.1/lib/flipper/middleware/setup_env.rb:35:in `call'
#     vendor/bundle/gems/rack-2.0.7/lib/rack/tempfile_reaper.rb:15:in `call'
#     vendor/bundle/gems/rack-2.0.7/lib/rack/etag.rb:25:in `call'
#     vendor/bundle/gems/rack-2.0.7/lib/rack/conditional_get.rb:25:in `call'
#     vendor/bundle/gems/rack-2.0.7/lib/rack/head.rb:12:in `call'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
#     vendor/bundle/gems/rack-2.0.7/lib/rack/session/abstract/id.rb:232:in `context'
#     vendor/bundle/gems/rack-2.0.7/lib/rack/session/abstract/id.rb:226:in `call'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/middleware/cookies.rb:670:in `call'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
#     vendor/bundle/gems/activesupport-5.2.3/lib/active_support/callbacks.rb:98:in `run_callbacks'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
#     vendor/bundle/gems/railties-5.2.3/lib/rails/rack/logger.rb:38:in `call_app'
#     vendor/bundle/gems/railties-5.2.3/lib/rails/rack/logger.rb:26:in `block in call'
#     vendor/bundle/gems/activesupport-5.2.3/lib/active_support/tagged_logging.rb:71:in `block in tagged'
#     vendor/bundle/gems/activesupport-5.2.3/lib/active_support/tagged_logging.rb:28:in `tagged'
#     vendor/bundle/gems/activesupport-5.2.3/lib/active_support/tagged_logging.rb:71:in `tagged'
#     vendor/bundle/gems/railties-5.2.3/lib/rails/rack/logger.rb:26:in `call'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/middleware/request_id.rb:27:in `call'
#     vendor/bundle/gems/rack-2.0.7/lib/rack/method_override.rb:22:in `call'
#     vendor/bundle/gems/rack-2.0.7/lib/rack/runtime.rb:22:in `call'
#     vendor/bundle/gems/activesupport-5.2.3/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/middleware/executor.rb:14:in `call'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/middleware/static.rb:127:in `call'
#     vendor/bundle/gems/rack-2.0.7/lib/rack/sendfile.rb:111:in `call'
#     vendor/bundle/gems/railties-5.2.3/lib/rails/engine.rb:524:in `call'
#     vendor/bundle/gems/rack-test-1.1.0/lib/rack/mock_session.rb:29:in `request'
#     vendor/bundle/gems/rack-test-1.1.0/lib/rack/test.rb:266:in `process_request'
#     vendor/bundle/gems/rack-test-1.1.0/lib/rack/test.rb:119:in `request'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/testing/integration.rb:263:in `process'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/testing/integration.rb:18:in `get'
#     vendor/bundle/gems/actionpack-5.2.3/lib/action_dispatch/testing/integration.rb:350:in `block (2 levels) in <module:Runner>'
#     vendor/bundle/gems/rails-controller-testing-1.0.4/lib/rails/controller/testing/integration.rb:13:in `block (2 levels) in <module:Integration>'
#     test/integration/api_v2_test.rb:104:in `block in <class:ApiV2Test>'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest/test.rb:98:in `block (3 levels) in run'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest/test.rb:195:in `capture_exceptions'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest/test.rb:95:in `block (2 levels) in run'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest.rb:270:in `time_it'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest/test.rb:94:in `block in run'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest.rb:365:in `on_signal'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest/test.rb:211:in `with_info_handler'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest/test.rb:93:in `run'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest.rb:1029:in `run_one_method'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest.rb:339:in `run_one_method'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest.rb:326:in `block (2 levels) in run'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest.rb:325:in `each'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest.rb:325:in `block in run'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest.rb:365:in `on_signal'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest.rb:352:in `with_info_handler'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest.rb:324:in `run'
#     vendor/bundle/gems/railties-5.2.3/lib/rails/test_unit/line_filtering.rb:10:in `run'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest.rb:164:in `block in __run'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest.rb:164:in `map'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest.rb:164:in `__run'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest.rb:141:in `run'
#     vendor/bundle/gems/minitest-5.13.0/lib/minitest.rb:68:in `block in autorun'