reidmorrison/symmetric-encryption

Using attr_encrypted consumes a db connection from the connection_pool indefinitely

azrosen92 opened this issue · 1 comments

azrosen92 commented

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_name

in 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.