ActiveRecord connections leaking when referencing an undefined local in a class method

[nullstyle]

I couldn't easily decide if this is a celluloid or an activerecord issue, so I'm deciding to post this here first. Apologies if this would better be submitted to activerecord's repo.

Repro code: https://github.com/nullstyle/celluloid-ar-leaker

Overview

When referencing an undefined local variable or calling an undefined method within
a class method defined on an ActiveRecord::Base subclass in the calling context of a
Celluloid::Pool, ActiveRecord connection objects are not properly returned to the
connection pool.

Notes:

• This behavior only exhibits itself with when in a class method of an AR::Base
  subclass. The following does not trigger the leak: Calling an instance method
  on an AR::Base subclass, calling a class method on a non-AR::Base subclass,
  calling a module method.
• This behavior seems specific to the exception raised when referencing an undefined
  local. The following does not trigger the leak: Referencing an undefined constant,
  raising a NameError directly, raising any other Exception.
• I was not able to re-produce this behavior using Thread or Fiber directly.
• I did not test for reproduction on any other DB than postgresql.

[tarcieri]

I'm not sure what to tell you besides "don't do that"?

Why are you calling undefined locals/methods in the first place?

[nullstyle]

I was not doing it intentionally :) In my specific case, a typo in my model was triggering connection pool exhaustion in my test suite.

Certainly, my solution at the time was to correct the typo. Regardless, It's not expected behavior and so my thought was that it could trip someone else up as well, hence the report. Would it better to put this in the gotchas page?

[tarcieri]

Sure? Seems like the real solution is to fix the bugs in your code 😉

[halorgium]

This does seem to be a bug with the Celluloid::Pool implementation.
The pool actors seem to be holding onto the connections.

I have more debugging available at nullstyle/celluloid-ar-leaker#1

[halorgium]

I have tracked things further.
When the connection is being released after the block completes, the current_connection_id is not in the set of reserved connections and it is therefore not checked back into the pool.

[halorgium]

This is incorrect. The release_connection method is still called when a connection is not checked out.
Back to it.

[halorgium]

This is a scary backtrace.

activerecord-4.1.9/lib/active_record/connection_adapters/abstract/connection_pool.rb:265:in `block in connection'
monitor.rb:211:in `mon_synchronize'
activerecord-4.1.9/lib/active_record/connection_adapters/abstract/connection_pool.rb:264:in `connection'
activerecord-4.1.9/lib/active_record/connection_adapters/abstract/connection_pool.rb:563:in `retrieve_connection'
activerecord-4.1.9/lib/active_record/connection_handling.rb:113:in `retrieve_connection'
activerecord-4.1.9/lib/active_record/connection_handling.rb:87:in `connection'
activerecord-4.1.9/lib/active_record/model_schema.rb:209:in `table_exists?'
activerecord-4.1.9/lib/active_record/core.rb:129:in `inspect'
celluloid-0.16.0/lib/celluloid/exceptions.rb:20:in `to_str'
celluloid-0.16.0/lib/celluloid/exceptions.rb:20:in `to_s'
celluloid-0.16.0/lib/celluloid/exceptions.rb:20:in `inspect'
celluloid-0.16.0/lib/celluloid/exceptions.rb:20:in `initialize'
celluloid-0.16.0/lib/celluloid.rb:316:in `new'
celluloid-0.16.0/lib/celluloid.rb:316:in `abort'
celluloid-0.16.0/lib/celluloid/pool_manager.rb:47:in `rescue in _send_'
celluloid-0.16.0/lib/celluloid/pool_manager.rb:53:in `_send_'
celluloid-0.16.0/lib/celluloid/pool_manager.rb:140:in `method_missing'
celluloid-0.16.0/lib/celluloid/calls.rb:26:in `public_send'
celluloid-0.16.0/lib/celluloid/calls.rb:26:in `dispatch'
celluloid-0.16.0/lib/celluloid/calls.rb:63:in `dispatch'
celluloid-0.16.0/lib/celluloid/cell.rb:60:in `block in invoke'
celluloid-0.16.0/lib/celluloid/cell.rb:71:in `block in task'
celluloid-0.16.0/lib/celluloid/actor.rb:357:in `block in task'
celluloid-0.16.0/lib/celluloid/tasks.rb:57:in `block in initialize'
celluloid-0.16.0/lib/celluloid/tasks/task_fiber.rb:15:in `block in create'

[mperham]

What? You don't think calling inspect on an AR class should hit the database? Seems totally legit, bro.

[halorgium]

@mperham or on an exception caused by AR

[halorgium]

This bug is independent of the Pool implementation. That code just exacerbates the problem.

@nullstyle can you confirm that this branch fixes the problem? https://github.com/celluloid/celluloid/compare/no-crash-exceptions

[halorgium]

This is backtrace when running in pooled-mode.

rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:265:in `block in connection'
monitor.rb:211:in `mon_synchronize'
rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:264:in `connection'
rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:564:in `retrieve_connection'
rails/activerecord/lib/active_record/connection_handling.rb:113:in `retrieve_connection'
rails/activerecord/lib/active_record/connection_handling.rb:87:in `connection'
rails/activerecord/lib/active_record/model_schema.rb:209:in `table_exists?'
rails/activerecord/lib/active_record/core.rb:129:in `inspect'
celluloid/lib/celluloid/exceptions.rb:20:in `to_str'
celluloid/lib/celluloid/exceptions.rb:20:in `to_s'
celluloid/lib/celluloid/exceptions.rb:20:in `inspect'
celluloid/lib/celluloid/exceptions.rb:20:in `initialize'
celluloid/lib/celluloid.rb:316:in `new'
celluloid/lib/celluloid.rb:316:in `abort'
celluloid/lib/celluloid/pool_manager.rb:47:in `rescue in _send_'
celluloid/lib/celluloid/pool_manager.rb:53:in `_send_'
celluloid/lib/celluloid/pool_manager.rb:140:in `method_missing'
celluloid/lib/celluloid/calls.rb:26:in `public_send'
celluloid/lib/celluloid/calls.rb:26:in `dispatch'
celluloid/lib/celluloid/calls.rb:63:in `dispatch'
celluloid/lib/celluloid/cell.rb:60:in `block in invoke'
celluloid/lib/celluloid/cell.rb:71:in `block in task'
celluloid/lib/celluloid/actor.rb:358:in `block in task'
celluloid/lib/celluloid/tasks.rb:57:in `block in initialize'
celluloid/lib/celluloid/tasks/task_fiber.rb:15:in `block in create'

[halorgium]

I have pushed a new PR: nullstyle/celluloid-ar-leaker#2
The main issue is that several parts of Celluloid assume that an exception is a safe object to inspect.
It is somewhat dubious that a connection is checked out and not re-checked in during the inspect (as part of the table_exists?.

[nullstyle]

@halorgium your branch at https://github.com/celluloid/celluloid/compare/no-crash-exceptions does indeed fix the problem for me :) Thanks so much for digging into it!

[halorgium]

@nullstyle you'll still have problems with pools, because that is a different code path.

[halorgium]

@tarcieri it turns out that if a Call is aborted via an AR exception (one which calls into table_exists?), the mere wrapping of the exception in AbortError will cause this issue.

[halorgium]

Seems like this is an OK commit: halorgium/rails@8599bf2

[halorgium]

A simpler repro: https://gist.github.com/halorgium/2778b0db4286b907343a

[tarcieri]

Closing as stale. If you are still interested in this issue, please reopen it.