Report stored procedure errors when using info messages

[bvogelzang]

Summary

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 mistakenly 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.

Example

Given this procedure:

CREATE PROCEDURE tinytds_TestPrintWithError
AS
    PRINT 'hello'
    RAISERROR('Error following print', 16, 1)

Result:

@client = TinyTds::Client.new({host: 'localhost', username: 'tinytds', password: '', database: 'tinytdstest', message_handler: Proc.new { |m| puts "Info: #{m.message}" }})
@client.execute("exec tinytds_TestPrintWithError").do

# Before - no error raised

Info: hello
=> -1

# After - error properly raised

Info: hello
Traceback (most recent call last):
        ...
        1: from (irb):10:in `do'
TinyTds::Error (Error following print)

Notes

• The memory management could use some extra attention. Curious to hear thoughts on how this should be handled or improved.

[aharpervc]

This looks really good, and I also see that CI has passed, which is a good sign. I think this can probably be merged after 2.1.3 is released.

[aharpervc]

Idea: can something be done to flush the error array, and if so, would that address this bug: https://github.com/rails-sqlserver/tiny_tds/issues/445

[bvogelzang]

I can't think of a way to adjust this in a way that would ultimately solve the timeout issue. See my commit message here: https://github.com/rails-sqlserver/tiny_tds/compare/master...bvogelzang:network-timeout-handling.

In cases of network failure I think the problem is:

1. dbcancel does not succeed because of the network failure
2. dbsqlok does not return due to above until the underlying network timeout on the os is hit.
3. TinyTds does not throw an error in the expected timeout window.

To really fix that issue we'd need some way to detect the difference between a timeout error on the happy path (with working network) vs. the bad path (with network failure). Otherwise we can't branch accordingly. It would be nice if we could detect if dbcancel has failed for this purpose but it looks like it always returns SUCCEED at the moment 😞 https://github.com/FreeTDS/freetds/blob/master/src/dblib/dblib.c#L3411.

[bvogelzang]

@metaskills, @larskanis, @coderjoe, @wpolicarpo any chance for getting a review on this PR, https://github.com/rails-sqlserver/tiny_tds/pull/483, and https://github.com/rails-sqlserver/tiny_tds/pull/481

[bvogelzang]

These changes are now available to test in 2.1.4.pre

[aharpervc]

~I'm testing this with 2.1.4.pre and I'm still not seeing both message from your example sp. I get the initial hello, but then no subsequent error. If I decrease the severity to a message, I still only see hello.~

Never mind, this must have been an issue on my own system. Verifying that I'm running 2.1.4.pre from rubygems, the example script does work now. That's with freetds v1.1.24 and v1.00.112. I suspect that there might be an older version of freetds that has a problem, but given that recent versions work this PR seems okay to merge to me.

[aharpervc]

While testing https://github.com/rails-sqlserver/tiny_tds/pull/481 I noticed that only raiserror ... with nowait seems to be displayed when there's a timeout, while print and raiserror without nowait didn't.

• is this expected?
• can we figure out how to flush whatever buffer has these messages when there's an error?
• should we have tests for this situation?

example script (basically the same as the other PR):

require 'tiny_tds'

def w(*args)
  puts [Thread.current.object_id, *args].join ' '
end

t = Thread.new do
  i = 0
  loop do
    i += 1
    w i
    sleep(1)
  end
end

c = TinyTds::Client.new({
  host: 'localhost',
  username: 'sa',
  password: 'Testing123@@',

  timeout: 5,
  login_timeout: 5,

  message_handler: ->(e) { w e },
})

w TinyTds::VERSION

sql = <<~SQL
create or alter procedure tinytds_TestPrintWithError
as
begin
    print 'print 1' -- nope
    raiserror('raiserror 1', 1, 1) -- nope
    -- raiserror('raiserror 2', 1, 1) with nowait -- yep, and uncommenting this will show all 3 messages

    waitfor delay '00:01:00'
end
SQL

w c.execute(sql).to_a
w c.execute('exec tinytds_TestPrintWithError').to_a

t.exit

raiserror with nowait commented out:

$ bundle exec ruby .\scratch.rb
24279960 1
18084080 2.1.4.pre
18084080
24279960 2
24279960 3
24279960 4
24279960 5
24279960 6
Traceback (most recent call last):
        2: from ./scratch.rb:42:in `<main>'
        1: from ./scratch.rb:42:in `to_a'
./scratch.rb:42:in `each': Adaptive Server connection timed out (TinyTds::Error)

uncommented:

$ bundle exec ruby .\scratch.rb
28287960 1
18149600 2.1.4.pre
18149600
28287960 2
28287960 3
28287960 4
28287960 5
28287960 6
18149600 print 1
18149600 raiserror 1
18149600 raiserror 2
Traceback (most recent call last):
        2: from ./scratch.rb:42:in `<main>'
        1: from ./scratch.rb:42:in `to_a'
./scratch.rb:42:in `each': Adaptive Server connection timed out (TinyTds::Error)

[bvogelzang]

is this expected?

I'm not exactly sure. This really just comes down to the order of when freetds notifies tiny_tds of the info message. With nowait in this scenario freetds calls the dbmsghandle before the dberrhandle. Without it, freetds calls the dbmsghandle after calling the dberrhandle. It's unclear to me if this is what should be happening or if this is a ordering bug within freetds.

can we figure out how to flush whatever buffer has these messages when there's an error?

Yes, we can definitely do this. These info messages are being pushed to our nonblocking_errors array which means we have access to them in novgl_cleanup. We just need to look past any errors in the array for any remaining info messages. e.g

for (short int i = 0; i < userdata->nonblocking_errors_length; i++) {
    tinytds_errordata error = userdata->nonblocking_errors[i];

    // look ahead to drain any info messages ahead of raising an 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.is_message,
            msg_error.cancel,
            msg_error.error,
            msg_error.source,
            msg_error.severity,
            msg_error.dberr,
            msg_error.oserr
          );
        }
      }
    }

    rb_tinytds_raise_error(client,
      error.is_message,
      error.cancel,
      error.error,
      error.source,
      error.severity,
      error.dberr,
      error.oserr
    );
  }

I'm trying to come up with a reason we wouldn't want to do this but can't really think of a downside.

should we have tests for this situation?

Yes, we probably should.

[aharpervc]

These changes look good to me. We've been testing 2.1.4-pre2 in production for a week or so and this change seems to have the intended outcome.

Can you squash/edit your commits down to whatever's appropriate for master history before merging?