From 293fe1f7e18c5df85cf4c9f97ccd317566e22e2e Mon Sep 17 00:00:00 2001 From: Ben Vogelzang Date: Wed, 5 May 2021 12:10:39 -0500 Subject: [PATCH] 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. --- CHANGELOG.md | 1 + ext/tiny_tds/client.c | 99 ++++++++++++++++++++++++------------------- ext/tiny_tds/client.h | 8 ++-- ext/tiny_tds/result.c | 31 +++++++++----- test/result_test.rb | 43 ++++++++++++++++++- test/test_helper.rb | 38 ++++++++++++++++- 6 files changed, 160 insertions(+), 60 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index f6f12c63..594e4298 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,6 +1,7 @@ ## (unreleased) * Improve handling of network related timeouts +* Fix error reporting when preceded by info message ## 2.1.3 diff --git a/ext/tiny_tds/client.c b/ext/tiny_tds/client.c index 3619cf9a..a65208df 100644 --- a/ext/tiny_tds/client.c +++ b/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) { diff --git a/ext/tiny_tds/client.h b/ext/tiny_tds/client.h index 5e5c811f..dcd6087c 100644 --- a/ext/tiny_tds/client.h +++ b/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 diff --git a/ext/tiny_tds/result.c b/ext/tiny_tds/result.c index 3b7ad7cb..8541c6b4 100644 --- a/ext/tiny_tds/result.c +++ b/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) { diff --git a/test/result_test.rb b/test/result_test.rb index 63649d4b..e40217f4 100644 --- a/test/result_test.rb +++ b/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 - diff --git a/test/test_helper.rb b/test/test_helper.rb index fc364b42..66f56d1c 100644 --- a/test/test_helper.rb +++ b/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}"