formatted_patch_1205_retry_logic_issue_31_as_of_05_04_2010.diff

From 54799c96a46237c101cc9290d89a86610a17d14c Mon Sep 17 00:00:00 2001
From: Joe Rafaniello <jrafanie@gmail.com>
Date: Tue, 4 May 2010 13:13:27 -0400
Subject: [PATCH] Squashed commit of the following:

commit a5f3f44c88e848f6862632e3f3587efb9bc9e4b9
Author: Joe Rafaniello <jrafanie@gmail.com>
Date:   Tue May 4 13:03:47 2010 -0400

    -Fixed transaction location to public methods.
    -Use @logger since logger method is not defined

commit f9611b15fc57054eb0c7e80d016edba4aef002dc
Author: Joe Rafaniello <jrafanie@gmail.com>
Date:   Tue May 4 11:56:11 2010 -0400

    Squashed commit of the following:

    commit 3a4fd24e447f4bf5916a9d77444e8513993c0b50
    Author: Joe Rafaniello <jrafanie@gmail.com>
    Date:   Tue May 4 11:09:44 2010 -0400

        Strip any company stuff

    commit cd9d166353b4cb7ac7885ce41664e9dbebb987f6
    Author: Joe Rafaniello <jrafanie@gmail.com>
    Date:   Wed Apr 21 11:57:59 2010 -0400

        Cleanup after merging upstream changes (support for returning multiple
        result sets, issues #29):
        Initialize the local variable outside the block, because it is only
        set within a block and later is returned outside the block.  Move begin/ensure
        handle cleanup logic into the loop.

    commit 9536776df4e9e2e02764474ad655356027b190af
    Author: Joe Rafaniello <jrafanie@gmail.com>
    Date:   Wed Apr 14 18:11:23 2010 -0400

        More 1205 deadlock victim cleanup:
        Create error_is_a_1205? method to be more DRY.
        Bring over log method so it doesn't change our exception in the case of 1205 and miss our retry logic.
        In transaction, SQL server will automatically rollback on a 1205 "deadlock victim" error so don't initiate a rollback and instead retry the transaction.

    commit da0c75fb3eaea478646508e90ab95de4ba1bd9d2
    Author: Joe Rafaniello <jrafanie@gmail.com>
    Date:   Wed Apr 14 18:07:35 2010 -0400

        Move ensure finish statement handle from handle_as_array to raw_select since that's where it's created

    commit 978ba0d6b2832bfc0b34caba8cbda1f2c9016050
    Author: Joe Rafaniello <jrafanie@gmail.com>
    Date:   Wed Apr 14 18:05:42 2010 -0400

        Don't reconnect when in the middle of a transaction

    commit 6c03b45a016246e99ea75feb21ce592f36e05835
    Author: Joe Rafaniello <jrafanie@gmail.com>
    Date:   Wed Apr 14 18:04:54 2010 -0400

        Ternary operator is great but you don't know what method call blew up when looking at the line number in the callstack.

    commit 637512df7a2f6253ec71c58d9edb844ed2eb3537
    Author: Joe Rafaniello <jrafanie@gmail.com>
    Date:   Wed Apr 14 18:03:55 2010 -0400

        Ensure we finish the statement handle in spid method

    commit e2712eccbf771956a483d6ce7a420add76f65ae0
    Author: Joe Rafaniello <jrafanie@gmail.com>
    Date:   Tue Apr 13 11:01:48 2010 -0400

        Log messages as warnings since that's what they are.

    commit 60995a0d03beeba7fdb3d94ba909e4d64202274f
    Author: Joe Rafaniello <jrafanie@gmail.com>
    Date:   Tue Apr 13 11:01:12 2010 -0400

        Add methods to retrieve database version, product version, product level, and edition:
        Ie: product version: 10.0.2531.0, product level: SP1, edition: Enterprise Edition (64-bit)

    commit 5531436c380a299654db4de480366d3a05d9a018
    Author: Joe Rafaniello <jrafanie@gmail.com>
    Date:   Tue Apr 13 14:54:22 2010 -0400

        Do not use do_execute and it's auto-reconnect logic for commit_db_transaction/rollback_db_transaction since we could get a new connection without the transaction context.

    commit fde84f1597e62800e9574e8c80487a92cbe24e4e
    Author: Joe Rafaniello <jrafanie@gmail.com>
    Date:   Tue Apr 13 13:45:10 2010 -0400

        Retry ODBC::Error 1205 Deadlock victim errors: (http://stackoverflow.com/questions/1980937/list-of-sql-server-errors-that-should-be-retried)

        If in a transaction, retry in the overloaded transaction method, otherwise, retry in the raw_connection_run/raw_connection_do.
        Log up to 4k of the sql statement.
        In raw_select, retry the whole method since this error could occur when requesting the handle or whenever we fetch rows on this handle.

        Wrap the whole raw_select in a log block to get full timings to get the statement handle, fetch each row, and store all the rows in memory.
        In handle_as_array, ensure that we finish the statement handle since we could get an error such as the 1205 in the middle of the method and leak the handle.

    commit 48d2a55833630b05adef345d936e37992d4a4a35
    Author: Joe Rafaniello <jrafanie@gmail.com>
    Date:   Tue Apr 13 13:41:59 2010 -0400

        Tests for connection isolation level, lock timeout, and spid

    commit 12faea458050c04fe4f9c112196188b20da163fb
    Author: Joe Rafaniello <jrafanie@gmail.com>
    Date:   Tue Apr 13 11:18:17 2010 -0400

        Add connection options which set class variables for transaction isolation level and lock timeout.
        Add spid method so we can log server pids.
        Apply lock timeout, trans isolation level, and log the spid during initialize and in reconnect!
---
 .../connection_adapters/sqlserver_adapter.rb       |  206 ++++++++++++++++++--
 test/cases/connection_test_sqlserver.rb            |   71 +++++++-
 2 files changed, 253 insertions(+), 24 deletions(-)

diff --git a/lib/active_record/connection_adapters/sqlserver_adapter.rb b/lib/active_record/connection_adapters/sqlserver_adapter.rb
index 0968b7d..839782f 100644
--- a/lib/active_record/connection_adapters/sqlserver_adapter.rb
+++ b/lib/active_record/connection_adapters/sqlserver_adapter.rb
@@ -31,11 +31,11 @@ module ActiveRecord
     protected
     
     def self.did_retry_sqlserver_connection(connection,count)
-      logger.info "CONNECTION RETRY: #{connection.class.name} retry ##{count}."
+      @logger.warn "CONNECTION RETRY: #{connection.class.name} retry ##{count}." if @logger
     end
     
     def self.did_lose_sqlserver_connection(connection)
-      logger.info "CONNECTION LOST: #{connection.class.name}"
+      @logger.warn "CONNECTION LOST: #{connection.class.name}" if @logger
     end
     
   end
@@ -175,9 +175,15 @@ module ActiveRecord
         :odbc   => [/link failure/, /server failed/, /connection was already closed/, /invalid handle/i],
         :adonet => [/current state is closed/, /network-related/]
       }
+
+      # Timeout error is raised differently depending on the patch level of
+      # ruby 1.8.6. Patch 111 raises Timeout::Error and 287 raises
+      # Timeout::ExitException.
+      TIMEOUT_ERROR = Timeout.const_defined?(:ExitException) ? Timeout::ExitException : Timeout::Error
+
       
       cattr_accessor :native_text_database_type, :native_binary_database_type, :native_string_database_type,
-                     :log_info_schema_queries, :enable_default_unicode_types, :auto_connect
+                     :log_info_schema_queries, :enable_default_unicode_types, :auto_connect, :transaction_isolation_level, :lock_timeout
       
       class << self
         
@@ -189,16 +195,34 @@ module ActiveRecord
       
       def initialize(logger,config)
         @connection_options = config
+        @sql_retry_message_length = 4096
         connect
         super(raw_connection, logger)
         initialize_sqlserver_caches
         unless SUPPORTED_VERSIONS.include?(database_year)
           raise NotImplementedError, "Currently, only #{SUPPORTED_VERSIONS.to_sentence} are supported."
         end
+
+        apply_connection_config
+        @logger.info "(#{adapter_name}.initialize) SPID: [#{spid}]" if @logger
       end
       
       # ABSTRACT ADAPTER =========================================#
-      
+
+      def apply_connection_config
+        @connection_options[:trans_isolation_level] ||= @@transaction_isolation_level
+        @connection_options[:lock_timeout]          ||= @@lock_timeout
+        @logger.info "(#{adapter_name}.apply_connection_config) trans_isolation_level: [#{@connection_options[:trans_isolation_level]}], lock_timeout: [#{@connection_options[:lock_timeout]}]" if @logger
+
+        # IMPORTANT:  Perform all executes with the raw_connection as we could already be in a auto reconnect log block, ie, don't use do_execute
+        begin
+          raw_connection_do("SET TRANSACTION ISOLATION LEVEL #{@connection_options[:trans_isolation_level]}") unless @connection_options[:trans_isolation_level].nil?
+          raw_connection_do("SET LOCK_TIMEOUT #{@connection_options[:lock_timeout]}") unless @connection_options[:lock_timeout].nil?
+        rescue
+          raise unless @auto_connecting
+        end
+      end
+
       def adapter_name
         ADAPTER_NAME
       end
@@ -242,11 +266,39 @@ module ActiveRecord
       def version
         self.class::VERSION
       end
-      
+
+      def detailed_database_version
+        "product version: #{product_version}, product level: #{product_level}, edition: #{edition}"
+      end
+
+      def product_version
+        @product_version ||= info_schema_query { select_value("SELECT CAST(SERVERPROPERTY('productversion') AS VARCHAR(128))")}
+      end
+
+      def product_level
+        @product_level ||= info_schema_query { select_value("SELECT CAST(SERVERPROPERTY('productlevel') AS VARCHAR(128))")}
+      end
+
+      def edition
+        @edition ||= info_schema_query { select_value("SELECT CAST(SERVERPROPERTY('edition') AS VARCHAR(128))")}
+      end
+
+      def spid
+        # Since spid method is called in the reconnect logic, we need to run the query outside of the log and auto reconnect block via raw_connection.run
+        @spid = raw_connection.run("SELECT @@spid") do |sth|
+          begin
+            res = sth.fetch
+            res.respond_to?(:first) ? res.first : res
+          ensure
+            finish_statement_handle(sth)
+          end
+        end
+      end
+
       def inspect
         "#<#{self.class} version: #{version}, year: #{database_year}, connection_options: #{@connection_options.inspect}>"
       end
-      
+
       def auto_connect
         @@auto_connect.is_a?(FalseClass) ? false : true
       end
@@ -339,6 +391,8 @@ module ActiveRecord
       def reconnect!
         disconnect!
         connect
+        apply_connection_config
+        @logger.info "(#{adapter_name}.reconnect!) SPID: [#{spid}]" if @logger
         active?
       end
 
@@ -410,11 +464,13 @@ module ActiveRecord
       end
 
       def commit_db_transaction
-        do_execute "COMMIT TRANSACTION"
+        sql = "COMMIT TRANSACTION"
+        log(sql, 'EXECUTE') { raw_connection_do(sql) }
       end
 
       def rollback_db_transaction
-        do_execute "ROLLBACK TRANSACTION" rescue nil
+        sql = "ROLLBACK TRANSACTION"
+        log(sql, 'EXECUTE') { raw_connection_do(sql) }  rescue nil
       end
       
       def create_savepoint
@@ -427,6 +483,43 @@ module ActiveRecord
       def rollback_to_savepoint
         do_execute "ROLLBACK TRANSACTION #{current_savepoint_name}"
       end
+
+      # Wrap a block in a transaction.  Returns result of block.
+      def transaction(start_db_transaction = true)
+        transaction_open = false
+        begin
+          if block_given?
+            if start_db_transaction
+              begin_db_transaction
+              transaction_open = true
+            end
+            yield
+          end
+        rescue Exception => err
+          if transaction_open
+            transaction_open = false
+            if error_is_a_1205?(err)
+              # TODO: Parse error to extract the sql statement so it can be logged.
+              # SQL Server rolls back transaction when raising 1205 error
+              @logger.warn("(#{adapter_name}.transaction) SPID: [#{@spid}] Retrying due to 1205 response from sql server...") if @logger
+              retry
+            else
+              rollback_db_transaction
+            end
+          end
+
+          raise unless err.is_a? ActiveRecord::Rollback
+        end
+      ensure
+        if transaction_open
+          begin
+            commit_db_transaction
+          rescue Exception => err
+            rollback_db_transaction
+            raise
+          end
+        end
+      end
       
       def add_limit_offset!(sql, options)
         # Validate and/or convert integers for :limit and :offets options.
@@ -807,6 +900,7 @@ module ActiveRecord
       
       def auto_reconnected?
         return false unless auto_connect
+        return false if self.open_transactions > 0 # don't switch connection if in the middle of a transaction
         @auto_connecting = true
         count = 0
         while count <= 5
@@ -825,7 +919,19 @@ module ActiveRecord
         with_auto_reconnect do
           case connection_mode
           when :odbc
-            block_given? ? raw_connection.run_block(sql) { |handle| yield(handle) } : raw_connection.run(sql)
+            begin
+              if block_given? 
+                raw_connection.run_block(sql) { |handle| yield(handle) }
+              else
+                raw_connection.run(sql)
+              end
+            rescue ODBC::Error => e # Retry ODBC 1205 "deadlock victim" errors
+              if error_is_a_1205?(e) && self.open_transactions == 0
+                @logger.warn("(#{adapter_name}.raw_connection_run) SPID: [#{@spid}] Retrying due to 1205 response from sql server... SQL: [#{sql.to_s[0..@sql_retry_message_length]}]") if @logger
+                retry
+              end
+              raise
+            end
           else :adonet
             raw_connection.create_command.tap{ |cmd| cmd.command_text = sql }.execute_reader
           end
@@ -835,7 +941,15 @@ module ActiveRecord
       def raw_connection_do(sql)
         case connection_mode
         when :odbc
-          raw_connection.do(sql)
+          begin
+            raw_connection.do(sql)
+          rescue ODBC::Error => e # Retry ODBC 1205 "deadlock victim" errors
+            if error_is_a_1205?(e) && self.open_transactions == 0
+              @logger.warn("(#{adapter_name}.raw_connection_do) SPID: [#{@spid}] Retrying due to 1205 response from sql server... SQL: [#{sql.to_s[0..@sql_retry_message_length]}]") if @logger
+              retry
+            end
+            raise
+          end
         else :adonet
           raw_connection.create_command.tap{ |cmd| cmd.command_text = sql }.execute_non_query
         end
@@ -897,19 +1011,28 @@ module ActiveRecord
         fields_and_row_sets = []
         log(sql,name) do
           begin
+            handle = nil
             handle = raw_connection_run(sql)
-            loop do
-              fields_and_rows = case connection_mode
-                                when :odbc
-                                  handle_to_fields_and_rows_odbc(handle)
-                                when :adonet
-                                  handle_to_fields_and_rows_adonet(handle)
-                                end
-              fields_and_row_sets << fields_and_rows
-              break unless handle_more_results?(handle)
+            begin
+              loop do
+                fields_and_rows = case connection_mode
+                                  when :odbc
+                                    handle_to_fields_and_rows_odbc(handle)
+                                  when :adonet
+                                    handle_to_fields_and_rows_adonet(handle)
+                                  end
+                fields_and_row_sets << fields_and_rows
+                break unless handle_more_results?(handle)
+              end
+            ensure
+              finish_statement_handle(handle)
             end
-          ensure
-            finish_statement_handle(handle)
+          rescue ODBC::Error => e # Retry ODBC 1205 "deadlock victim" errors
+            if error_is_a_1205?(e)
+              @logger.warn("(#{adapter_name}.raw_select) SPID: [#{@spid}] Retrying due to 1205 response from sql server... SQL: [#{sql.to_s[0..@sql_retry_message_length]}]") if @logger
+              retry
+            end
+            raise
           end
         end
         fields_and_row_sets
@@ -1050,6 +1173,47 @@ module ActiveRecord
       
       # HELPER METHODS ===========================================#
       
+      def log(sql, name)
+        if block_given?
+          result = nil
+          seconds = Benchmark.realtime { result = yield }
+          @runtime += seconds
+          log_info(sql, name, seconds)
+          result
+        else
+          log_info(sql, name, 0)
+          nil
+        end
+      rescue TIMEOUT_ERROR => e
+        # Rescue timeout error seperately to avoid getting it raised as ActiveRecord::StatementInvalid
+        message = "Super class: [#{e.class.superclass.name}], Class: [#{e.class.name}], Message: [#{e.message}], Sql: [#{sql[0..1000]}...]" # need to reference superclass because the timeout implementation creates a subclass
+        @logger.error("(abstract_adapter) Name: [#{name}], Message: [#{message}]") if @logger
+        @logger.info("(abstract_adapter) Verifying DB connection after timeout error") if @logger
+        begin
+          verify!
+        rescue => err
+          @logger.info("(abstract_adapter) Reconnecting after timeout error failed due to err: Class: [#{err.class.name}], Message: [#{err.message}]") if @logger
+        end
+        raise e
+      rescue Exception => e
+        raise if error_is_a_1205?(e)
+        
+        # Log message and raise exception.
+        # Set last_verification to 0, so that connection gets verified
+        # upon reentering the request loop
+        @last_verification = 0
+        message = "#{e.class.name}: #{e.message}: #{sql[0..1000]}..."
+        log_info(message, name, 0)
+
+        @logger.error("(abstract_adapter) Name: [#{name}], Message: [#{message}]") if @logger
+
+        raise ActiveRecord::StatementInvalid, message
+      end
+
+      def error_is_a_1205?(err)
+        err.kind_of?(ODBC::Error) && err.message.include?("(1205)")
+      end
+      
       def insert_sql?(sql)
         !(sql =~ /^\s*INSERT/i).nil?
       end
diff --git a/test/cases/connection_test_sqlserver.rb b/test/cases/connection_test_sqlserver.rb
index f2dafbe..0453ec0 100644
--- a/test/cases/connection_test_sqlserver.rb
+++ b/test/cases/connection_test_sqlserver.rb
@@ -98,10 +98,75 @@ class ConnectionTestSqlserver < ActiveRecord::TestCase
         assert_raise(ActiveRecord::StatementInvalid) { Topic.count }
       end
     end
-    
+
+    context "spid method" do
+      setup do
+        @spid = @connection.spid
+      end
+
+      should "return a fixnum" do
+        assert @spid.is_a?(Fixnum)
+      end
+
+      should "set instance variable" do
+        assert_equal @spid, @connection.instance_variable_get(:@spid)
+      end
+    end
+
+    context "connection transaction isolation level" do
+      setup do
+        @iso_level = "READ UNCOMMITTED"
+        @connection.transaction_isolation_level = @iso_level
+      end
+
+      teardown do
+        @connection.transaction_isolation_level = nil
+        opts = @connection.instance_variable_get(:@connection_options).merge({:trans_isolation_level => nil})
+        @connection.instance_variable_set(:@connection_options, opts)
+      end
+
+      should "set Adapter class variable" do
+        assert_equal @iso_level, ActiveRecord::ConnectionAdapters::SQLServerAdapter.transaction_isolation_level
+      end
+
+      should 'apply isolation level via apply_connection_config' do
+        assert_nothing_raised() {@connection.apply_connection_config}
+      end
+
+      should 'apply isolation level on reconnect!' do
+        ActiveRecord::ConnectionAdapters::SQLServerAdapter.any_instance.expects(:apply_connection_config)
+        assert_nothing_raised() {@connection.reconnect!}
+      end
+    end
+
+    context "connection lock timeout" do
+      setup do
+        @lock_timeout = 30000
+        @connection.lock_timeout = @lock_timeout
+      end
+
+      teardown do
+        @connection.lock_timeout = nil
+        opts = @connection.instance_variable_get(:@connection_options).merge({:lock_timeout => nil})
+        @connection.instance_variable_set(:@connection_options, opts)
+      end
+
+      should "set Adapter class variable" do
+        assert_equal @lock_timeout, ActiveRecord::ConnectionAdapters::SQLServerAdapter.lock_timeout
+      end
+
+      should 'apply lock timeout via apply_connection_config' do
+        assert_nothing_raised() {@connection.apply_connection_config}
+      end
+
+      should 'apply lock timeout on reconnect!' do
+        ActiveRecord::ConnectionAdapters::SQLServerAdapter.any_instance.expects(:apply_connection_config)
+        assert_nothing_raised() {@connection.reconnect!}
+      end
+    end
   end
-  
-  
+
+
   
   private
   
-- 
1.6.5

gistfile2.txt