bad bug in DM/DO nested transactions (FIXED in 03ae081f28a6143478e2174ccf3bd233e82cb91b)

1_bar.rb

#!/usr/bin/ruby

[
    'addressable.git', 'extlib.git',
    'do.git/data_objects', 'do.git/do_mysql',
    'dm-core.git', 'dm-migrations.git', 'dm-transactions.git', 'dm-do-adapter.git', 'dm-mysql-adapter-1.0.0',
].each do |path|
    $:.unshift "common/gems/#{path}/lib"
end

require 'data_objects'
require 'dm-core'
require 'dm-migrations'
require 'dm-transactions'

class Foo
    include ::DataMapper::Resource

    property :id, Serial
end

class Bar
    include ::DataMapper::Resource

    property :id, Serial
    property :dongs, String
    property :balls, String
end

::DataMapper.setup(:default, 'mysql://127.0.0.1/test')
::DataMapper.auto_migrate!


def log(msg)
    warn "[#{Thread.current.object_id}] #{msg}"
end


log "starting"

mutex = Mutex.new
cv = ConditionVariable.new

Thread.new do
    Thread.abort_on_exception = true

    while true
        log "thread: txn 1 start"
        Foo.transaction do
            Foo.first(:id => 1)

            log "thread: txn 2 start"
            Foo.transaction do
                begin
                    Foo.first(:id => 1)
                rescue Exception => e
                    log "ERROR: #{e.inspect} (#{e.backtrace})"
                    exit!
                end
            end
            log "thread: txn 2 end"
        end

        log "thread: txn 1 end"

        cv.signal
    end
end

while true
    $FOO or mutex.synchronize { cv.wait(mutex) } and $FOO = true

    log "main: get"

    begin
        Bar.first(:id => 1)
    rescue Exception => e
        log "ERROR: #{e.inspect} (#{e.backtrace})"
        exit!
    end
end

2_outputs.txt

$ ruby bar.rb
starting
thread: txn 1 start
thread: txn 2 start
thread: txn 2 end
thread: txn 1 end
main: get
thread: txn 1 start
ERROR: #<ArgumentError: Field-count mismatch. Expected 3 fields, but the query yielded 1> (./common/gems/dm-do-
adapter.git/lib/dm-do-adapter/adapter.rb:145:in `execute_reader'./common/gems/dm-do-adapter.git/lib/dm-do-
adapter/adapter.rb:145:in `read'./common/gems/dm-do-adapter.git/lib/dm-do-adapter/adapter.rb:268:in 
`with_connection'./common/gems/dm-do-adapter.git/lib/dm-do-adapter/adapter.rb:141:in `read'./common/gems/dm-core.git/lib/dm-
core/repository.rb:162:in `read'./common/gems/dm-core.git/lib/dm-core/model.rb:370:in `first'bar.rb:80)

$ ruby bar.rb
starting
thread: txn 1 start
thread: txn 2 start
thread: txn 2 end
thread: txn 1 end
main: get
thread: txn 1 start
ERROR: #<DataObjects::SQLError: Lost connection to MySQL server during query (code: 2013, sql state: HY000, query: SELECT 
`id`, `dongs`, `balls` FROM `bars` WHERE `id` = 1 ORDER BY `id` LIMIT 1, uri: mysql://localhost/test)> (./common/gems/dm-do-
adapter.git/lib/dm-do-adapter/adapter.rb:145:in `execute_reader'./common/gems/dm-do-adapter.git/lib/dm-do-
adapter/adapter.rb:145:in `read'./common/gems/dm-do-adapter.git/lib/dm-do-adapter/adapter.rb:268:in 
`with_connection'./common/gems/dm-do-adapter.git/lib/dm-do-adapter/adapter.rb:141:in `read'./common/gems/dm-core.git/lib/dm-
core/repository.rb:162:in `read'./common/gems/dm-core.git/lib/dm-core/model.rb:370:in `first'bar.rb:76)

$ ruby bar.rb
starting
thread: txn 1 start
thread: txn 2 start
thread: txn 2 end
thread: txn 1 end
main: get
thread: txn 1 start
ERROR: #<NoMethodError: undefined method `close' for nil:NilClass> (./common/gems/dm-do-adapter.git/lib/dm-do-
adapter/adapter.rb:152:in `read'./common/gems/dm-do-adapter.git/lib/dm-do-adapter/adapter.rb:268:in 
`with_connection'./common/gems/dm-do-adapter.git/lib/dm-do-adapter/adapter.rb:141:in `read'./common/gems/dm-core.git/lib/dm-
core/repository.rb:162:in `read'./common/gems/dm-core.git/lib/dm-core/model.rb:370:in `first'bar.rb:75)

$ ruby bar.rb
starting
thread: txn 1 start
thread: txn 2 start
thread: txn 2 end
thread: txn 1 end
main: get
thread: txn 1 start
./common/gems/do.git/data_objects/lib/data_objects/transaction.rb:58:in `execute_non_query': Bad file descriptor (Errno::EBADF)
	from ./common/gems/do.git/data_objects/lib/data_objects/transaction.rb:58:in `run'
	from ./common/gems/do.git/data_objects/lib/data_objects/transaction.rb:39:in `begin'
	from ./common/gems/dm-transactions.git/lib/dm-transactions.rb:288:in `send'
	from ./common/gems/dm-transactions.git/lib/dm-transactions.rb:288:in `do_adapter'
	from ./common/gems/dm-transactions.git/lib/dm-transactions.rb:325:in `begin_adapter'
	from ./common/gems/dm-transactions.git/lib/dm-transactions.rb:250:in `send'
	from ./common/gems/dm-transactions.git/lib/dm-transactions.rb:250:in `each_adapter'
	from ./common/gems/dm-transactions.git/lib/dm-transactions.rb:249:in `each_key'
	from ./common/gems/dm-transactions.git/lib/dm-transactions.rb:249:in `each_adapter'
	from ./common/gems/dm-transactions.git/lib/dm-transactions.rb:109:in `begin'
	from ./common/gems/dm-transactions.git/lib/dm-transactions.rb:130:in `commit'
	from ./common/gems/dm-transactions.git/lib/dm-transactions.rb:373:in `transaction'
	from bar.rb:47
	from bar.rb:41:in `initialize'
	from bar.rb:41:in `new'
	from bar.rb:41

3_notes.txt

- Ruby 1.8.7 p174 (OSX) and REE 2010.02 (Linux)
- DM *EDGE* (dm-core, dm-transactions)
- DO *EDGE*
- MySQL Server 5.x

Bugs:

  - do_mysql cCommand_execute_reader is expected by dm-do-adapter to always return a result.  
    - There is one case where it returns Qnil, but the error is obscured at the DM level by dm-do-adapter's ensure block 
ignoring the exception, but firing one of its own (should be NoMethodError of nil#next!, instead you get NoMethodError of 
nil#close). 
    - When it returns Qnil, I think it's because the connection was dropped, but mysql_errno/mysql_error are empty.  This 
suggests that some undiscovered error condition in DM's invocation of DO lurks (but it's not clear who should have 
responsibility for defending against getting into this condition in the first place).

4_adapter.diff

diff --git a/lib/dm-do-adapter/adapter.rb b/lib/dm-do-adapter/adapter.rb
index 0bd53cc..93fc418 100644
--- a/lib/dm-do-adapter/adapter.rb
+++ b/lib/dm-do-adapter/adapter.rb
@@ -240,13 +240,16 @@ module DataMapper
         #
         # @api semipublic
         def open_connection
-          DataObjects::Connection.new(normalized_uri)
+          foo = DataObjects::Connection.new(normalized_uri)
+          warn "[#{Thread.current.object_id}] DO open_connection = #{foo.object_id}"
+          foo
         end
 
         # Takes connection and closes it
         #
         # @api semipublic
         def close_connection(connection)
+          warn "[#{Thread.current.object_id}] DO close_connection(#{connection.object_id}) (current = #{connection.object_id})"
           connection.close if connection.respond_to?(:close)
         end
       end

5_dm_do_adapter.diff

diff --git a/lib/dm-transactions/adapters/dm-do-adapter.rb b/lib/dm-transactions/adapters/dm-do-adapter.rb
index d6dffb9..0b0b98f 100644
--- a/lib/dm-transactions/adapters/dm-do-adapter.rb
+++ b/lib/dm-transactions/adapters/dm-do-adapter.rb
@@ -66,11 +66,14 @@ module DataMapper
 
         # @api semipublic
         def open_connection
-          current_connection || super
+          foo = current_connection || super
+          warn "[#{Thread.current.object_id}] TXN open_connection = #{foo.object_id} (current = #{current_connection.object_id})"
+          foo
         end
 
         # @api semipublic
         def close_connection(connection)
+          warn "[#{Thread.current.object_id}] TXN close_connection(#{connection.object_id}) (current = #{current_connection.object_id})
           super unless current_connection.equal?(connection)
         end
       end

6_data_objects.diff

diff --git a/data_objects/lib/data_objects/pooling.rb b/data_objects/lib/data_objects/pooling.rb
index 28fa9d4..421ac5a 100644
--- a/data_objects/lib/data_objects/pooling.rb
+++ b/data_objects/lib/data_objects/pooling.rb
@@ -190,21 +190,31 @@ module DataObjects
             end
           end
         end until instance
+        warn "[#{Thread.current.object_id}] POOL: acquire #{instance.object_id}"
+        _show_state
         instance
       end
 
       def release(instance)
         lock.synchronize do
+          warn "[#{Thread.current.object_id}] POOL: release #{instance.object_id}"
           instance.instance_variable_set(:@__allocated_in_pool, Time.now)
           @used.delete(instance.object_id)
-          @available.push(instance)
+          @available.push(instance) unless @available.include?(instance)
+          _show_state
           wait.signal
         end
         nil
       end
 
+      def _show_state
+        warn "POOL: available = #{@available.map{|o| o.object_id}.join(',')}"
+        warn "POOL: used = #{@used.keys.join(',')}"
+      end
+
       def delete(instance)
         lock.synchronize do
+          warn "[#{Thread.current.object_id}] POOL: delete #{instance.object_id}"
           instance.instance_variable_set(:@__pool, nil)
           @used.delete(instance.object_id)
           wait.signal

7_another_trace(before_checking_@available_patch).txt

$ ruby bar.rb
[2148278700] POOL: acquire 2162530000
[2148278700] DO open_connection = 2162530000
[2148278700] TXN open_connection = 2162530000 (current = 4)
[2148278700] TXN close_connection(2162530000) (current = 4)
[2148278700] DO close_connection(2162530000) (current = 2162530000)
[2148278700] POOL: release 2162530000
[2148278700] POOL: acquire 2162530000
[2148278700] DO open_connection = 2162530000
[2148278700] TXN open_connection = 2162530000 (current = 4)
[2148278700] TXN close_connection(2162530000) (current = 4)
[2148278700] DO close_connection(2162530000) (current = 2162530000)
[2148278700] POOL: release 2162530000
[2148278700] POOL: acquire 2162530000
[2148278700] DO open_connection = 2162530000
[2148278700] TXN open_connection = 2162530000 (current = 4)
[2148278700] POOL: acquire 2162523280
[2148278700] DO open_connection = 2162523280
[2148278700] TXN open_connection = 2162523280 (current = 4)
[2148278700] TXN close_connection(2162523280) (current = 4)
[2148278700] DO close_connection(2162523280) (current = 2162523280)
[2148278700] POOL: release 2162523280
[2148278700] POOL: acquire 2162523280
[2148278700] DO open_connection = 2162523280
[2148278700] TXN open_connection = 2162523280 (current = 4)
[2148278700] TXN close_connection(2162523280) (current = 4)
[2148278700] DO close_connection(2162523280) (current = 2162523280)
[2148278700] POOL: release 2162523280
[2148278700] TXN close_connection(2162530000) (current = 4)
[2148278700] DO close_connection(2162530000) (current = 2162530000)
[2148278700] POOL: release 2162530000
[2148278700] POOL: acquire 2162530000
[2148278700] DO open_connection = 2162530000
[2148278700] TXN open_connection = 2162530000 (current = 4)
[2148278700] TXN close_connection(2162530000) (current = 4)
[2148278700] DO close_connection(2162530000) (current = 2162530000)
[2148278700] POOL: release 2162530000
[2148278700] POOL: acquire 2162530000
[2148278700] DO open_connection = 2162530000
[2148278700] TXN open_connection = 2162530000 (current = 4)
[2148278700] TXN close_connection(2162530000) (current = 4)
[2148278700] DO close_connection(2162530000) (current = 2162530000)
[2148278700] POOL: release 2162530000
[2148278700] POOL: acquire 2162530000
[2148278700] DO open_connection = 2162530000
[2148278700] TXN open_connection = 2162530000 (current = 4)
[2148278700] TXN close_connection(2162530000) (current = 4)
[2148278700] DO close_connection(2162530000) (current = 2162530000)
[2148278700] POOL: release 2162530000
[2148278700] starting
[2162514260] thread: txn 1 start
[2162514260] POOL: acquire 2162530000
[2162514260] TXN open_connection = 2162530000 (current = 2162530000)
[2162514260] TXN close_connection(2162530000) (current = 2162530000)
[2162514260] thread: txn 2 start
[2162514260] TXN open_connection = 2162530000 (current = 2162530000)
[2162514260] TXN close_connection(2162530000) (current = 2162530000)
[2162514260] POOL: release 2162530000
[2162514260] thread: txn 2 end
[2162514260] POOL: release 2162530000
[2162514260] thread: txn 1 end
[2148278700] main: get
[2148278700] POOL: acquire 2162530000
[2148278700] DO open_connection = 2162530000
[2148278700] TXN open_connection = 2162530000 (current = 4)
[2162514260] thread: txn 1 start
[2162514260] POOL: acquire 2162530000
[2148278700] TXN close_connection(2162530000) (current = 4)
[2148278700] DO close_connection(2162530000) (current = 2162530000)
[2148278700] POOL: release 2162530000
[2148278700] ERROR: #<NoMethodError: undefined method `close' for nil:NilClass> (./common/gems/dm-do-adapter.git/lib/dm-do-adapter/adapter.rb:152:in `read'./common/gems/dm-do-adapter.git/lib/dm-do-adapter/adapter.rb:271:in `with_connection'./common/gems/dm-do-adapter.git/lib/dm-do-adapter/adapter.rb:141:in `read'./common/gems/dm-core.git/lib/dm-core/repository.rb:162:in `read'./common/gems/dm-core.git/lib/dm-core/model.rb:370:in `first'bar.rb:81)

8_and_another(after_checking_@available_patch,still_ends_in_failure).txt

$ ruby bar.rb
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2148278700] POOL: acquire 2162521140
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162521140
[2148278700] TXN open_connection = 2162521140 (current = 4)
[2148278700] TXN close_connection(2162521140) (current = 4)
[2148278700] DO close_connection(2162521140) (current = 2162521140)
[2148278700] POOL: release 2162521140
POOL: available = 2162521140
POOL: used = 2162528760
[2148278700] POOL: acquire 2162521140
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162521140
[2148278700] TXN open_connection = 2162521140 (current = 4)
[2148278700] TXN close_connection(2162521140) (current = 4)
[2148278700] DO close_connection(2162521140) (current = 2162521140)
[2148278700] POOL: release 2162521140
POOL: available = 2162521140
POOL: used = 2162528760
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162521140,2162528760
POOL: used = 
[2148278700] POOL: acquire 2162528760
POOL: available = 2162521140
POOL: used = 2162528760
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162521140,2162528760
POOL: used = 
[2148278700] POOL: acquire 2162528760
POOL: available = 2162521140
POOL: used = 2162528760
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162521140,2162528760
POOL: used = 
[2148278700] POOL: acquire 2162528760
POOL: available = 2162521140
POOL: used = 2162528760
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162521140,2162528760
POOL: used = 
[2148278700] starting
[2162510120] thread: txn 1 start
[2162510120] current transactions = nil
[2162510120] POOL: acquire 2162528760
POOL: available = 2162521140
POOL: used = 2162528760
[2162510120] TXN open_connection = 2162528760 (current = 2162528760)
[2162510120] TXN close_connection(2162528760) (current = 2162528760)
[2162510120] thread: txn 2 start
[2162510120] TXN open_connection = 2162528760 (current = 2162528760)
[2162510120] TXN close_connection(2162528760) (current = 2162528760)
[2162510120] POOL: release 2162528760
POOL: available = 2162521140,2162528760
POOL: used = 
[2162510120] thread: txn 2 end
[2162510120] POOL: release 2162528760
POOL: available = 2162521140,2162528760
POOL: used = 
[2162510120] thread: txn 1 end
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 2162521140
POOL: used = 2162528760
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] thread: txn 1 start
[2162510120] current transactions = {2162591540=>[]}
[2162510120] POOL: acquire 2162521140
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] TXN open_connection = 2162521140 (current = 2162521140)
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] TXN close_connection(2162521140) (current = 2162521140)
[2162510120] thread: txn 2 start
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] TXN open_connection = 2162521140 (current = 2162521140)
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] TXN close_connection(2162521140) (current = 2162521140)
[2162510120] POOL: release 2162521140
POOL: available = 2162521140
POOL: used = 2162528760
[2162510120] thread: txn 2 end
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162521140,2162528760
POOL: used = 
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 2162521140
POOL: used = 2162528760
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] POOL: release 2162521140
POOL: available = 2162521140
POOL: used = 2162528760
[2162510120] thread: txn 1 end
[2162510120] thread: txn 1 start
[2162510120] current transactions = {2162591540=>[]}
[2162510120] POOL: acquire 2162521140
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] TXN open_connection = 2162521140 (current = 2162521140)
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] TXN close_connection(2162521140) (current = 2162521140)
[2162510120] thread: txn 2 start
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] TXN open_connection = 2162521140 (current = 2162521140)
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] TXN close_connection(2162521140) (current = 2162521140)
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] POOL: release 2162521140
POOL: available = 2162521140
POOL: used = 2162528760
[2162510120] thread: txn 2 end
[2162510120] POOL: release 2162521140
POOL: available = 2162521140
POOL: used = 2162528760
[2162510120] thread: txn 1 end
[2162510120] thread: txn 1 start
[2162510120] current transactions = {2162591540=>[]}
[2162510120] POOL: acquire 2162521140
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] TXN open_connection = 2162521140 (current = 2162521140)
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] TXN close_connection(2162521140) (current = 2162521140)
[2162510120] thread: txn 2 start
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] TXN open_connection = 2162521140 (current = 2162521140)
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] TXN close_connection(2162521140) (current = 2162521140)
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] POOL: release 2162521140
POOL: available = 2162521140
POOL: used = 2162528760
[2162510120] thread: txn 2 end
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162521140,2162528760
POOL: used = 
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 2162521140
POOL: used = 2162528760
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] POOL: release 2162521140
POOL: available = 2162521140
POOL: used = 2162528760
[2162510120] thread: txn 1 end
[2162510120] thread: txn 1 start
[2162510120] current transactions = {2162591540=>[]}
[2162510120] POOL: acquire 2162521140
POOL: available = 
POOL: used = 2162528760,2162521140
[2162510120] TXN open_connection = 2162521140 (current = 2162521140)
[2162510120] TXN close_connection(2162521140) (current = 2162521140)
[2162510120] thread: txn 2 start
[2162510120] TXN open_connection = 2162521140 (current = 2162521140)
[2162510120] TXN close_connection(2162521140) (current = 2162521140)
[2162510120] POOL: release 2162521140
POOL: available = 2162521140
POOL: used = 2162528760
[2162510120] thread: txn 2 end
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162521140,2162528760
POOL: used = 
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 2162521140
POOL: used = 2162528760
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] POOL: release 2162521140
POOL: available = 2162521140
POOL: used = 2162528760
[2162510120] thread: txn 1 end
[2162510120] thread: txn 1 start
[2162510120] current transactions = {2162591540=>[]}
[2162510120] POOL: acquire 2162521140
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] TXN open_connection = 2162521140 (current = 2162521140)
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] TXN close_connection(2162521140) (current = 2162521140)
[2162510120] thread: txn 2 start
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] TXN open_connection = 2162521140 (current = 2162521140)
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2148278700] POOL: acquire 2162528760
POOL: available = 
POOL: used = 2162528760,2162521140
[2148278700] DO open_connection = 2162528760
[2148278700] TXN open_connection = 2162528760 (current = 4)
[2162510120] TXN close_connection(2162521140) (current = 2162521140)
[2148278700] TXN close_connection(2162528760) (current = 4)
[2148278700] DO close_connection(2162528760) (current = 2162528760)
[2148278700] POOL: release 2162528760
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] main: get
[2162510120] POOL: release 2162521140
POOL: available = 2162528760,2162521140
POOL: used = 
[2162510120] thread: txn 2 end
[2148278700] POOL: acquire 2162521140
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] DO open_connection = 2162521140
[2148278700] TXN open_connection = 2162521140 (current = 4)
[2162510120] POOL: release 2162521140
POOL: available = 2162528760,2162521140
POOL: used = 
[2162510120] thread: txn 1 end
[2162510120] thread: txn 1 start
[2162510120] current transactions = {2162591540=>[]}
[2162510120] POOL: acquire 2162521140
POOL: available = 2162528760
POOL: used = 2162521140
[2148278700] TXN close_connection(2162521140) (current = 4)
[2148278700] DO close_connection(2162521140) (current = 2162521140)
[2148278700] POOL: release 2162521140
POOL: available = 2162528760,2162521140
POOL: used = 
[2148278700] ERROR: #<NoMethodError: undefined method `close' for nil:NilClass> (./common/gems/dm-do-adapter.git/lib/dm-do-adapter/adapter.rb:152:in `read'./common/gems/dm-do-adapter.git/lib/dm-do-adapter/adapter.rb:271:in `with_connection'./common/gems/dm-do-adapter.git/lib/dm-do-adapter/adapter.rb:141:in `read'./common/gems/dm-core.git/lib/dm-core/repository.rb:162:in `read'./common/gems/dm-core.git/lib/dm-core/model.rb:370:in `first'bar.rb:81)
$