Fix error reporting when preceded by info message (#475)

Capturing errors while in a non-blocking state was originally structured to capture a single error. This was intentional in order to avoid capturing more generic info messages that FreeTDS might send before the Global VM Lock was obtained. In most circumstances this is what we want. However, now that we capture info messages it is possible that a info message will be stored and the actual runtime error will be discarded as non-important. The result is that while a runtime error is reported in the database, a TinyTds error is never thrown and only the info message is handled. A subset of this problem is that only one info message can be captured while in non-blocking mode which prevents stored procedures from reporting multiple info messages to TinyTds.

To fix this issue, the reported messages are stored within a dynamic array of tinytds_errordata structs, then processed normally once the GVL is obtained.

Given the fact that we don't know the number of messages that will be sent, we dynamically manage and re-allocate memory for the nonblocking_errors array as needed. We can't use the ruby C API because it is not safe to call while in a non-blocking state as shown by #133.

Author: bvogelzang

CHANGELOG.md

@@ -1,6 +1,7 @@
 ## (unreleased)
 
 * Improve handling of network related timeouts
+* Fix error reporting when preceded by info message
 
 ## 2.1.3
 

ext/tiny_tds/client.c

@@ -24,25 +24,25 @@ VALUE opt_escape_regex, opt_escape_dblquote;
 
 // Lib Backend (Helpers)
 
-VALUE rb_tinytds_raise_error(DBPROCESS *dbproc, int is_message, int cancel, const char *error, const char *source, int severity, int dberr, int oserr) {
+VALUE rb_tinytds_raise_error(DBPROCESS *dbproc, tinytds_errordata error) {
   VALUE e;
   GET_CLIENT_USERDATA(dbproc);
-  if (cancel && !dbdead(dbproc) && userdata && !userdata->closed) {
+  if (error.cancel && !dbdead(dbproc) && userdata && !userdata->closed) {
     userdata->dbsqlok_sent = 1;
     dbsqlok(dbproc);
     userdata->dbcancel_sent = 1;
     dbcancel(dbproc);
   }
-  e = rb_exc_new2(cTinyTdsError, error);
-  rb_funcall(e, intern_source_eql, 1, rb_str_new2(source));
-  if (severity)
-    rb_funcall(e, intern_severity_eql, 1, INT2FIX(severity));
-  if (dberr)
-    rb_funcall(e, intern_db_error_number_eql, 1, INT2FIX(dberr));
-  if (oserr)
-    rb_funcall(e, intern_os_error_number_eql, 1, INT2FIX(oserr));
-
-  if (severity <= 10 && is_message) {
+  e = rb_exc_new2(cTinyTdsError, error.error);
+  rb_funcall(e, intern_source_eql, 1, rb_str_new2(error.source));
+  if (error.severity)
+    rb_funcall(e, intern_severity_eql, 1, INT2FIX(error.severity));
+  if (error.dberr)
+    rb_funcall(e, intern_db_error_number_eql, 1, INT2FIX(error.dberr));
+  if (error.oserr)
+    rb_funcall(e, intern_os_error_number_eql, 1, INT2FIX(error.oserr));
+
+  if (error.severity <= 10 && error.is_message) {
     VALUE message_handler = userdata && userdata->message_handler ? userdata->message_handler : Qnil;
     if (message_handler && message_handler != Qnil && rb_respond_to(message_handler, intern_call) != 0) {
       rb_funcall(message_handler, intern_call, 1, e);
@@ -57,6 +57,16 @@ VALUE rb_tinytds_raise_error(DBPROCESS *dbproc, int is_message, int cancel, cons
 
 
 // Lib Backend (Memory Management & Handlers)
+static void push_userdata_error(tinytds_client_userdata *userdata, tinytds_errordata error) {
+  // reallocate memory for the array as needed
+  if (userdata->nonblocking_errors_size == userdata->nonblocking_errors_length) {
+    userdata->nonblocking_errors_size *= 2;
+    userdata->nonblocking_errors = realloc(userdata->nonblocking_errors, userdata->nonblocking_errors_size * sizeof(tinytds_errordata));
+  }
+
+  userdata->nonblocking_errors[userdata->nonblocking_errors_length] = error;
+  userdata->nonblocking_errors_length++;
+}
 
 int tinytds_err_handler(DBPROCESS *dbproc, int severity, int dberr, int oserr, char *dberrstr, char *oserrstr) {
   static const char *source = "error";
@@ -105,6 +115,16 @@ int tinytds_err_handler(DBPROCESS *dbproc, int severity, int dberr, int oserr, c
       break;
   }
 
+  tinytds_errordata error_data = {
+    .is_message = 0,
+    .cancel = cancel,
+    .severity = severity,
+    .dberr = dberr,
+    .oserr = oserr
+  };
+  strncpy(error_data.error, dberrstr, ERROR_MSG_SIZE);
+  strncpy(error_data.source, source, ERROR_MSG_SIZE);
+
   /*
   When in non-blocking mode we need to store the exception data to throw it
   once the blocking call returns, otherwise we will segfault ruby since part
@@ -116,27 +136,9 @@ int tinytds_err_handler(DBPROCESS *dbproc, int severity, int dberr, int oserr, c
       dbcancel(dbproc);
       userdata->dbcancel_sent = 1;
     }
-
-    /*
-    If we've already captured an error message, don't overwrite it. This is
-    here because FreeTDS sends a generic "General SQL Server error" message
-    that will overwrite the real message. This is not normally a problem
-    because a ruby exception is normally thrown and we bail before the
-    generic message can be sent.
-    */
-    if (!userdata->nonblocking_error.is_set) {
-      userdata->nonblocking_error.is_message = 0;
-      userdata->nonblocking_error.cancel = cancel;
-      strncpy(userdata->nonblocking_error.error, dberrstr, ERROR_MSG_SIZE);
-      strncpy(userdata->nonblocking_error.source, source, ERROR_MSG_SIZE);
-      userdata->nonblocking_error.severity = severity;
-      userdata->nonblocking_error.dberr = dberr;
-      userdata->nonblocking_error.oserr = oserr;
-      userdata->nonblocking_error.is_set = 1;
-    }
-
+    push_userdata_error(userdata, error_data);
   } else {
-    rb_tinytds_raise_error(dbproc, 0, cancel, dberrstr, source, severity, dberr, oserr);
+    rb_tinytds_raise_error(dbproc, error_data);
   }
 
   return return_value;
@@ -148,25 +150,31 @@ int tinytds_msg_handler(DBPROCESS *dbproc, DBINT msgno, int msgstate, int severi
 
   int is_message_an_error = severity > 10 ? 1 : 0;
 
+  tinytds_errordata error_data = {
+    .is_message = !is_message_an_error,
+    .cancel = is_message_an_error,
+    .severity = severity,
+    .dberr = msgno,
+    .oserr = msgstate
+  };
+  strncpy(error_data.error, msgtext, ERROR_MSG_SIZE);
+  strncpy(error_data.source, source, ERROR_MSG_SIZE);
+
   // See tinytds_err_handler() for info about why we do this
   if (userdata && userdata->nonblocking) {
-    if (!userdata->nonblocking_error.is_set) {
-      userdata->nonblocking_error.is_message = !is_message_an_error;
-      userdata->nonblocking_error.cancel = is_message_an_error;
-      strncpy(userdata->nonblocking_error.error, msgtext, ERROR_MSG_SIZE);
-      strncpy(userdata->nonblocking_error.source, source, ERROR_MSG_SIZE);
-      userdata->nonblocking_error.severity = severity;
-      userdata->nonblocking_error.dberr = msgno;
-      userdata->nonblocking_error.oserr = msgstate;
-      userdata->nonblocking_error.is_set = 1;
-    }
+    /*
+    In the case of non-blocking command batch execution we can receive multiple messages
+    (including errors). We keep track of those here so they can be processed once the
+    non-blocking call returns.
+    */
+    push_userdata_error(userdata, error_data);
 
     if (is_message_an_error && !dbdead(dbproc) && !userdata->closed) {
       dbcancel(dbproc);
       userdata->dbcancel_sent = 1;
     }
   } else {
-    rb_tinytds_raise_error(dbproc, !is_message_an_error, is_message_an_error, msgtext, source, severity, msgno, msgstate);
+    rb_tinytds_raise_error(dbproc, error_data);
   }
   return 0;
 }
@@ -204,7 +212,10 @@ static void rb_tinytds_client_reset_userdata(tinytds_client_userdata *userdata)
   userdata->dbsqlok_sent = 0;
   userdata->dbcancel_sent = 0;
   userdata->nonblocking = 0;
-  userdata->nonblocking_error.is_set = 0;
+  // the following is mainly done for consistency since the values are reset accordingly in nogvl_setup/cleanup.
+  // the nonblocking_errors array does not need to be freed here. That is done as part of nogvl_cleanup.
+  userdata->nonblocking_errors_length = 0;
+  userdata->nonblocking_errors_size = 0;
 }
 
 static void rb_tinytds_client_mark(void *ptr) {

ext/tiny_tds/client.h

@@ -5,9 +5,9 @@
 void init_tinytds_client();
 
 #define ERROR_MSG_SIZE 1024
+#define ERRORS_STACK_INIT_SIZE 2
 
 typedef struct {
-  short int is_set;
   int is_message;
   int cancel;
   char error[ERROR_MSG_SIZE];
@@ -25,7 +25,9 @@ typedef struct {
   RETCODE dbsqlok_retcode;
   short int dbcancel_sent;
   short int nonblocking;
-  tinytds_errordata nonblocking_error;
+  short int nonblocking_errors_length;
+  short int nonblocking_errors_size;
+  tinytds_errordata *nonblocking_errors;
   VALUE message_handler;
 } tinytds_client_userdata;
 
@@ -40,7 +42,7 @@ typedef struct {
   rb_encoding *encoding;
 } tinytds_client_wrapper;
 
-VALUE rb_tinytds_raise_error(DBPROCESS *dbproc, int is_message, int cancel, const char *error, const char *source, int severity, int dberr, int oserr);
+VALUE rb_tinytds_raise_error(DBPROCESS *dbproc, tinytds_errordata error);
 
 // Lib Macros
 

ext/tiny_tds/result.c

@@ -86,6 +86,9 @@ static void dbcancel_ubf(DBPROCESS *client) {
 static void nogvl_setup(DBPROCESS *client) {
   GET_CLIENT_USERDATA(client);
   userdata->nonblocking = 1;
+  userdata->nonblocking_errors_length = 0;
+  userdata->nonblocking_errors = malloc(ERRORS_STACK_INIT_SIZE * sizeof(tinytds_errordata));
+  userdata->nonblocking_errors_size = ERRORS_STACK_INIT_SIZE;
 }
 
 static void nogvl_cleanup(DBPROCESS *client) {
@@ -96,17 +99,25 @@ static void nogvl_cleanup(DBPROCESS *client) {
   Now that the blocking operation is done, we can finally throw any
   exceptions based on errors from SQL Server.
   */
-  if (userdata->nonblocking_error.is_set) {
-    userdata->nonblocking_error.is_set = 0;
-    rb_tinytds_raise_error(client,
-      userdata->nonblocking_error.is_message,
-      userdata->nonblocking_error.cancel,
-      userdata->nonblocking_error.error,
-      userdata->nonblocking_error.source,
-      userdata->nonblocking_error.severity,
-      userdata->nonblocking_error.dberr,
-      userdata->nonblocking_error.oserr);
+  for (short int i = 0; i < userdata->nonblocking_errors_length; i++) {
+    tinytds_errordata error = userdata->nonblocking_errors[i];
+
+    // lookahead to drain any info messages ahead of raising error
+    if (!error.is_message) {
+      for (short int j = i; j < userdata->nonblocking_errors_length; j++) {
+        tinytds_errordata msg_error = userdata->nonblocking_errors[j];
+        if (msg_error.is_message) {
+          rb_tinytds_raise_error(client, msg_error);
+        }
+      }
+    }
+
+    rb_tinytds_raise_error(client, error);
   }
+
+  free(userdata->nonblocking_errors);
+  userdata->nonblocking_errors_length = 0;
+  userdata->nonblocking_errors_size = 0;
 }
 
 static RETCODE nogvl_dbsqlok(DBPROCESS *client) {

test/result_test.rb

@@ -652,6 +652,48 @@ class ResultTest < TinyTds::TestCase
             assert_equal 1, messages.length, 'there should be one message after one print statement'
             assert_equal msg, m.message, 'message text'
           end
+
+          it 'must raise an error preceded by a `print` message' do
+            messages.clear
+            action = lambda { @client.execute("EXEC tinytds_TestPrintWithError").do }
+            assert_raise_tinytds_error(action) do |e|
+              assert_equal 'hello', messages.first.message, 'message text'
+
+              assert_equal "Error following print", e.message
+              assert_equal 16, e.severity
+              assert_equal 50000, e.db_error_number
+            end
+          end
+
+          it 'calls the provided message handler for each of a series of `print` messages' do
+            messages.clear
+            @client.execute("EXEC tinytds_TestSeveralPrints").do
+            assert_equal ['hello 1', 'hello 2', 'hello 3'], messages.map { |e| e.message }, 'message list'
+          end
+
+          it 'should flush info messages before raising error in cases of timeout' do
+            @client = new_connection timeout: 1, message_handler: Proc.new { |m| messages << m }
+            action = lambda { @client.execute("print 'hello'; waitfor delay '00:00:02'").do }
+            messages.clear
+            assert_raise_tinytds_error(action) do |e|
+              assert_match %r{timed out}i, e.message, 'ignore if non-english test run'
+              assert_equal 6, e.severity
+              assert_equal 20003, e.db_error_number
+              assert_equal 'hello', messages.first&.message, 'message text'
+            end
+          end
+
+          it 'should print info messages before raising error in cases of timeout' do
+            @client = new_connection timeout: 1, message_handler: Proc.new { |m| messages << m }
+            action = lambda { @client.execute("raiserror('hello', 1, 1) with nowait; waitfor delay '00:00:02'").do }
+            messages.clear
+            assert_raise_tinytds_error(action) do |e|
+              assert_match %r{timed out}i, e.message, 'ignore if non-english test run'
+              assert_equal 6, e.severity
+              assert_equal 20003, e.db_error_number
+              assert_equal 'hello', messages.first&.message, 'message text'
+            end
+          end
         end
 
         it 'must not raise an error when severity is 10 or less' do
@@ -770,4 +812,3 @@ def insert_and_select_datatype(datatype)
   end
 
 end
-

test/test_helper.rb

@@ -154,6 +154,8 @@ def load_current_schema
       loader.execute(drop_sql).do
       loader.execute(schema_sql).do
       loader.execute(sp_sql).do
+      loader.execute(sp_error_sql).do
+      loader.execute(sp_several_prints_sql).do
       loader.close
       true
     end
@@ -168,7 +170,16 @@ def drop_sql_sybase
         ) DROP TABLE datatypes
         IF EXISTS(
           SELECT 1 FROM sysobjects WHERE type = 'P' AND name = 'tinytds_TestReturnCodes'
-        ) DROP PROCEDURE tinytds_TestReturnCodes|
+        ) DROP PROCEDURE tinytds_TestReturnCodes
+        IF EXISTS(
+          SELECT 1 FROM sysobjects WHERE type = 'P' AND name = 'tinytds_TestPrintWithError'
+        ) DROP PROCEDURE tinytds_TestPrintWithError
+        IF EXISTS(
+          SELECT 1 FROM sysobjects WHERE type = 'P' AND name = 'tinytds_TestPrintWithError'
+        ) DROP PROCEDURE tinytds_TestPrintWithError
+        IF EXISTS(
+          SELECT 1 FROM sysobjects WHERE type = 'P' AND name = 'tinytds_TestSeveralPrints'
+        ) DROP PROCEDURE tinytds_TestSeveralPrints|
     end
 
     def drop_sql_microsoft
@@ -182,7 +193,15 @@ def drop_sql_microsoft
         IF EXISTS (
           SELECT name FROM sysobjects
           WHERE name = 'tinytds_TestReturnCodes' AND type = 'P'
-        ) DROP PROCEDURE tinytds_TestReturnCodes|
+        ) DROP PROCEDURE tinytds_TestReturnCodes
+        IF EXISTS (
+          SELECT name FROM sysobjects
+          WHERE name = 'tinytds_TestPrintWithError' AND type = 'P'
+        ) DROP PROCEDURE tinytds_TestPrintWithError
+        IF EXISTS (
+          SELECT name FROM sysobjects
+          WHERE name = 'tinytds_TestSeveralPrints' AND type = 'P'
+        ) DROP PROCEDURE tinytds_TestSeveralPrints|
     end
 
     def sp_sql
@@ -192,6 +211,21 @@ def sp_sql
         RETURN(420) |
     end
 
+    def sp_error_sql
+      %|CREATE PROCEDURE tinytds_TestPrintWithError
+        AS
+        PRINT 'hello'
+        RAISERROR('Error following print', 16, 1)|
+    end
+
+    def sp_several_prints_sql
+      %|CREATE PROCEDURE tinytds_TestSeveralPrints
+        AS
+        PRINT 'hello 1'
+        PRINT 'hello 2'
+        PRINT 'hello 3'|
+    end
+
     def find_value(id, column, query_options={})
       query_options[:timezone] ||= :utc
       sql = "SELECT [#{column}] FROM [datatypes] WHERE [id] = #{id}"