Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Using attr_encrypted consumes a db connection from the connection_pool indefinitely #132

Open
azrosen92 opened this issue Jul 30, 2019 · 1 comment
Open

Using attr_encrypted consumes a db connection from the connection_pool indefinitely #132

azrosen92 opened this issue Jul 30, 2019 · 1 comment

Comments

@azrosen92
Copy link

azrosen92 commented Jul 30, 2019 •
edited
Loading

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.
@amanfredi
Copy link

I am suspicious of this call to define_attribute_methods: https://github.com/rocketjob/symmetric-encryption/blob/45244135d07b47b79eb290686af5aff10a6aa853/lib/symmetric_encryption/active_record/attr_encrypted.rb#L46

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@amanfredi @azrosen92