Report stored procedure errors when using info messages

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}"