Using attr_encrypted consumes a db connection from the connection_pool indefinitely #132
Description
Environment
Provide at least:
- Ruby Version: 2.4.6
- Symmetric Encryption Version: 4.3.0
- Application/framework names and versions (e.g. Rails, Sinatra, Puma, etc.): Rails 4.2.11.1
I am running into an issue where including
attr_encrypted :column_namein one of my models results in the rails server starting with an open connection to the database. This means that when trying to make a request from the browser, the following exception is raised:
Rails -- Exception: ActiveRecord::ConnectionTimeoutError: could not obtain a database connection within 5.000 seconds (waited 5.000 seconds)
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:189:in `block in wait_poll'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:180:in `loop'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:180:in `wait_poll'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:135:in `block in poll'
/home/vagrant/.rvm/rubies/ruby-2.4.6/lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:145:in `synchronize'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:133:in `poll'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:425:in `acquire_connection'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:349:in `block in checkout'
/home/vagrant/.rvm/rubies/ruby-2.4.6/lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:348:in `checkout'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:263:in `block in connection'
/home/vagrant/.rvm/rubies/ruby-2.4.6/lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:262:in `connection'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:571:in `retrieve_connection'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activerecord-4.2.11.1/lib/active_record/connection_handling.rb:113:in `retrieve_connection'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activerecord-4.2.11.1/lib/active_record/connection_handling.rb:87:in `connection'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activerecord-4.2.11.1/lib/active_record/migration.rb:383:in `connection'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activerecord-4.2.11.1/lib/active_record/migration.rb:370:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/actionpack-4.2.11.1/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activesupport-4.2.11.1/lib/active_support/callbacks.rb:88:in `__run_callbacks__'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activesupport-4.2.11.1/lib/active_support/callbacks.rb:778:in `_run_call_callbacks'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activesupport-4.2.11.1/lib/active_support/callbacks.rb:81:in `run_callbacks'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/actionpack-4.2.11.1/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/actionpack-4.2.11.1/lib/action_dispatch/middleware/reloader.rb:73:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/actionpack-4.2.11.1/lib/action_dispatch/middleware/remote_ip.rb:78:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/better_errors-1.1.0/lib/better_errors/middleware.rb:58:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/actionpack-4.2.11.1/lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/actionpack-4.2.11.1/lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/railties-4.2.11.1/lib/rails/rack/logger.rb:38:in `call_app'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/rails_semantic_logger-4.2.1/lib/rails_semantic_logger/extensions/rails/rack/logger.rb:19:in `block in call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/semantic_logger-4.2.0/lib/semantic_logger/semantic_logger.rb:299:in `fast_tag'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/semantic_logger-4.2.0/lib/semantic_logger/base.rb:190:in `tagged'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/rails_semantic_logger-4.2.1/lib/rails_semantic_logger/extensions/rails/rack/logger.rb:19:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/rack-1.6.11/lib/rack/session/abstract/id.rb:225:in `context'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/rack-1.6.11/lib/rack/session/abstract/id.rb:220:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/actionpack-4.2.11.1/lib/action_dispatch/middleware/cookies.rb:560:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/request_store-1.3.1/lib/request_store/middleware.rb:9:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/actionpack-4.2.11.1/lib/action_dispatch/middleware/request_id.rb:21:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/rack-1.6.11/lib/rack/methodoverride.rb:22:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/rack-1.6.11/lib/rack/runtime.rb:18:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/activesupport-4.2.11.1/lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/rack-1.6.11/lib/rack/lock.rb:17:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/actionpack-4.2.11.1/lib/action_dispatch/middleware/static.rb:120:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/rack-1.6.11/lib/rack/sendfile.rb:113:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/rack-cors-0.4.1/lib/rack/cors.rb:81:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/rack-cors-0.4.1/lib/rack/cors.rb:81:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/sentry-raven-2.9.0/lib/raven/integrations/rack.rb:51:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/railties-4.2.11.1/lib/rails/engine.rb:518:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/railties-4.2.11.1/lib/rails/application.rb:165:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/rack-1.6.11/lib/rack/lock.rb:17:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/rack-1.6.11/lib/rack/content_length.rb:15:in `call'
/home/vagrant/.rvm/gems/ruby-2.4.6/gems/rack-1.6.11/lib/rack/handler/webrick.rb:88:in `service'
/home/vagrant/.rvm/rubies/ruby-2.4.6/lib/ruby/2.4.0/webrick/httpserver.rb:140:in `service'
/home/vagrant/.rvm/rubies/ruby-2.4.6/lib/ruby/2.4.0/webrick/httpserver.rb:96:in `run'
/home/vagrant/.rvm/rubies/ruby-2.4.6/lib/ruby/2.4.0/webrick/server.rb:308:in `block in start_thread'
I was able to "bandaid" the problem by increasing the pool size from 1 to 2, but I'd like to understand what's going on here.
For some more context, the connection that is left open looks like
=# select datid, datname, pid, usesysid, usename, application_name, state, query from pg_stat_activity;
datid | datname | pid | usesysid | usename | application_name | state | query
-------+--------------+------+----------+---------+------------------+--------+------------------------------------------------------------------------------------------------------
16394 | app_dev | 9221 | 16384 | vagrant | bin/rails | idle | SELECT a.attname, format_type(a.atttypid, a.atttypmod), +
| | | | | | | pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod +
| | | | | | | FROM pg_attribute a LEFT JOIN pg_attrdef d +
| | | | | | | ON a.attrelid = d.adrelid AND a.attnum = d.adnum +
| | | | | | | WHERE a.attrelid = '"shipper_applications"'::regclass +
| | | | | | | AND a.attnum > 0 AND NOT a.attisdropped +
| | | | | | | ORDER BY a.attnum +
| | | | | | |
16394 | app_dev | 7975 | 16384 | vagrant | psql | active | select datid, datname, pid, usesysid, usename, application_name, state, query from pg_stat_activity;This row appears after running bundle exec rails s. The shipper_applications table, is not the model that includes attr_encrypted.
And when I remove the call to attr_encrypted from my model and restart the rails server, I get
=# select datid, datname, pid, usesysid, usename, application_name, state, query from pg_stat_activity;
datid | datname | pid | usesysid | usename | application_name | state | query
-------+--------------+------+----------+---------+------------------+--------+------------------------------------------------------------------------------------------------------
16394 | app_dev | 7975 | 16384 | vagrant | psql | active | select datid, datname, pid, usesysid, usename, application_name, state, query from pg_stat_activity;which is what I'd expect.